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
diff --git a/audio_bluetooth_hw/device_port_proxy.cc b/audio_bluetooth_hw/device_port_proxy.cc
index 5b484b8..c7bf457 100644
--- a/audio_bluetooth_hw/device_port_proxy.cc
+++ b/audio_bluetooth_hw/device_port_proxy.cc
@@ -31,6 +31,8 @@
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 @@
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 @@
};
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 @@
.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 @@
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 @@
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 @@
}
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 @@
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 @@
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 @@
}
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 @@
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 @@
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 @@
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 @@
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 @@
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 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 @@
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_,
diff --git a/audio_hal_interface/client_interface.cc b/audio_hal_interface/client_interface.cc
index cc1c96e..e83ae84 100644
--- a/audio_hal_interface/client_interface.cc
+++ b/audio_hal_interface/client_interface.cc
@@ -75,7 +75,7 @@
auto hidl_retval =
provider_->streamStarted(BluetoothAudioCtrlAckToHalStatus(ack));
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal Failure";
+ LOG(ERROR) << __func__ << ": BluetoothAudioHal failure: " << hidl_retval.description();
}
}
return Void();
@@ -87,7 +87,7 @@
auto hidl_retval =
provider_->streamSuspended(BluetoothAudioCtrlAckToHalStatus(ack));
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal Failure";
+ LOG(ERROR) << __func__ << ": BluetoothAudioHal failure: " << hidl_retval.description();
}
}
return Void();
@@ -200,7 +200,7 @@
if (provider_ != nullptr) {
auto hidl_retval = provider_->unlinkToDeath(death_recipient_);
if (!hidl_retval.isOk()) {
- LOG(ERROR) << __func__ << ": BluetoothAudioDeathRecipient Failure";
+ LOG(FATAL) << __func__ << ": BluetoothAudioDeathRecipient failure: " << hidl_retval.description();
}
}
}
@@ -237,10 +237,10 @@
sink_->GetSessionType(), getProviderCapabilities_cb);
getProviderCapabilities_future.get();
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__
- << ": BluetoothAudioHal::getProviderCapabilities Failure";
+ LOG(FATAL) << __func__ << ": BluetoothAudioHal::getProviderCapabilities failure: " << hidl_retval.description();
return;
- } else if (capabilities_.empty()) {
+ }
+ if (capabilities_.empty()) {
LOG(WARNING) << __func__
<< ": SessionType=" << toString(sink_->GetSessionType())
<< " Not supported by BluetoothAudioHal";
@@ -267,12 +267,12 @@
providersFactory->openProvider(sink_->GetSessionType(), openProvider_cb);
openProvider_future.get();
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal::openProvider Failure";
+ LOG(FATAL) << __func__ << ": BluetoothAudioHal::openProvider failure: " << hidl_retval.description();
}
CHECK(provider_ != nullptr);
if (!provider_->linkToDeath(death_recipient_, 0).isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioDeathRecipient Failure";
+ LOG(FATAL) << __func__ << ": BluetoothAudioDeathRecipient failure: " << hidl_retval.description();
}
LOG(INFO) << "IBluetoothAudioProvidersFactory::openProvider() returned "
@@ -338,7 +338,7 @@
stack_if, sink_->GetAudioConfiguration(), hidl_cb);
hidl_startSession_future.get();
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal Failure";
+ LOG(FATAL) << __func__ << ": BluetoothAudioHal failure: " << hidl_retval.description();
return -EPROTO;
}
@@ -368,14 +368,15 @@
if (provider_ == nullptr) {
LOG(ERROR) << __func__ << ": BluetoothAudioHal nullptr";
return;
- } else if (ack == BluetoothAudioCtrlAck::PENDING) {
+ }
+ if (ack == BluetoothAudioCtrlAck::PENDING) {
LOG(INFO) << __func__ << ": " << ack << " ignored";
return;
}
BluetoothAudioStatus status = BluetoothAudioCtrlAckToHalStatus(ack);
auto hidl_retval = provider_->streamStarted(status);
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal Failure";
+ LOG(ERROR) << __func__ << ": BluetoothAudioHal failure: " << hidl_retval.description();
}
}
@@ -384,14 +385,15 @@
if (provider_ == nullptr) {
LOG(ERROR) << __func__ << ": BluetoothAudioHal nullptr";
return;
- } else if (ack == BluetoothAudioCtrlAck::PENDING) {
+ }
+ if (ack == BluetoothAudioCtrlAck::PENDING) {
LOG(INFO) << __func__ << ": " << ack << " ignored";
return;
}
BluetoothAudioStatus status = BluetoothAudioCtrlAckToHalStatus(ack);
auto hidl_retval = provider_->streamSuspended(status);
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal Failure";
+ LOG(ERROR) << __func__ << ": BluetoothAudioHal failure: " << hidl_retval.description();
}
}
@@ -410,7 +412,7 @@
mDataMQ = nullptr;
auto hidl_retval = provider_->endSession();
if (!hidl_retval.isOk()) {
- LOG(FATAL) << __func__ << ": BluetoothAudioHal Failure";
+ LOG(ERROR) << __func__ << ": BluetoothAudioHal failure: " << hidl_retval.description();
return -EPROTO;
}
return 0;