/*
* Copyright 2019 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include
#include
#include
#ifdef OS_ANDROID
#include
#endif
#include
#include
#include "btif_bqr.h"
#include "btif_common.h"
#include "btm_api.h"
#include "common/leaky_bonded_queue.h"
#include "common/time_util.h"
#include "osi/include/properties.h"
namespace bluetooth {
namespace bqr {
using bluetooth::common::LeakyBondedQueue;
using std::chrono::system_clock;
// The instance of BQR event queue
static std::unique_ptr> kpBqrEventQueue(
new LeakyBondedQueue(kBqrEventQueueSize));
void BqrVseSubEvt::ParseBqrLinkQualityEvt(uint8_t length,
uint8_t* p_param_buf) {
if (length < kLinkQualityParamTotalLen) {
LOG(FATAL) << __func__
<< ": Parameter total length: " << std::to_string(length)
<< " is abnormal. It shall be not shorter than: "
<< std::to_string(kLinkQualityParamTotalLen);
return;
}
STREAM_TO_UINT8(bqr_link_quality_event_.quality_report_id, p_param_buf);
STREAM_TO_UINT8(bqr_link_quality_event_.packet_types, p_param_buf);
STREAM_TO_UINT16(bqr_link_quality_event_.connection_handle, p_param_buf);
STREAM_TO_UINT8(bqr_link_quality_event_.connection_role, p_param_buf);
STREAM_TO_INT8(bqr_link_quality_event_.tx_power_level, p_param_buf);
STREAM_TO_INT8(bqr_link_quality_event_.rssi, p_param_buf);
STREAM_TO_UINT8(bqr_link_quality_event_.snr, p_param_buf);
STREAM_TO_UINT8(bqr_link_quality_event_.unused_afh_channel_count,
p_param_buf);
STREAM_TO_UINT8(bqr_link_quality_event_.afh_select_unideal_channel_count,
p_param_buf);
STREAM_TO_UINT16(bqr_link_quality_event_.lsto, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.connection_piconet_clock,
p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.retransmission_count, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.no_rx_count, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.nak_count, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.last_tx_ack_timestamp, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.flow_off_count, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.last_flow_on_timestamp, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.buffer_overflow_bytes, p_param_buf);
STREAM_TO_UINT32(bqr_link_quality_event_.buffer_underflow_bytes, p_param_buf);
const auto now = system_clock::to_time_t(system_clock::now());
localtime_r(&now, &tm_timestamp_);
}
void BqrVseSubEvt::WriteLmpLlTraceLogFile(int fd, uint8_t length,
uint8_t* p_param_buf) {
const auto now = system_clock::to_time_t(system_clock::now());
localtime_r(&now, &tm_timestamp_);
STREAM_TO_UINT8(bqr_log_dump_event_.quality_report_id, p_param_buf);
STREAM_TO_UINT16(bqr_log_dump_event_.connection_handle, p_param_buf);
length -= kLogDumpParamTotalLen;
bqr_log_dump_event_.vendor_specific_parameter = p_param_buf;
std::stringstream ss_log;
ss_log << "\n"
<< std::put_time(&tm_timestamp_, "%m-%d %H:%M:%S ")
<< "Handle: " << loghex(bqr_log_dump_event_.connection_handle)
<< " VSP: ";
TEMP_FAILURE_RETRY(write(fd, ss_log.str().c_str(), ss_log.str().size()));
TEMP_FAILURE_RETRY(
write(fd, bqr_log_dump_event_.vendor_specific_parameter, length));
LmpLlMessageTraceCounter++;
}
void BqrVseSubEvt::WriteBtSchedulingTraceLogFile(int fd, uint8_t length,
uint8_t* p_param_buf) {
const auto now = system_clock::to_time_t(system_clock::now());
localtime_r(&now, &tm_timestamp_);
STREAM_TO_UINT8(bqr_log_dump_event_.quality_report_id, p_param_buf);
STREAM_TO_UINT16(bqr_log_dump_event_.connection_handle, p_param_buf);
length -= kLogDumpParamTotalLen;
bqr_log_dump_event_.vendor_specific_parameter = p_param_buf;
std::stringstream ss_log;
ss_log << "\n"
<< std::put_time(&tm_timestamp_, "%m-%d %H:%M:%S ")
<< "Handle: " << loghex(bqr_log_dump_event_.connection_handle)
<< " VSP: ";
TEMP_FAILURE_RETRY(write(fd, ss_log.str().c_str(), ss_log.str().size()));
TEMP_FAILURE_RETRY(
write(fd, bqr_log_dump_event_.vendor_specific_parameter, length));
BtSchedulingTraceCounter++;
}
std::string BqrVseSubEvt::ToString() const {
std::stringstream ss;
ss << QualityReportIdToString(bqr_link_quality_event_.quality_report_id)
<< ", Handle: " << loghex(bqr_link_quality_event_.connection_handle)
<< ", " << PacketTypeToString(bqr_link_quality_event_.packet_types) << ", "
<< ((bqr_link_quality_event_.connection_role == 0) ? "Central"
: "Peripheral ")
<< ", PwLv: " << std::to_string(bqr_link_quality_event_.tx_power_level)
<< ", RSSI: " << std::to_string(bqr_link_quality_event_.rssi)
<< ", SNR: " << std::to_string(bqr_link_quality_event_.snr)
<< ", UnusedCh: "
<< std::to_string(bqr_link_quality_event_.unused_afh_channel_count)
<< ", UnidealCh: "
<< std::to_string(bqr_link_quality_event_.afh_select_unideal_channel_count)
<< ", ReTx: "
<< std::to_string(bqr_link_quality_event_.retransmission_count)
<< ", NoRX: " << std::to_string(bqr_link_quality_event_.no_rx_count)
<< ", NAK: " << std::to_string(bqr_link_quality_event_.nak_count)
<< ", FlowOff: " << std::to_string(bqr_link_quality_event_.flow_off_count)
<< ", OverFlow: "
<< std::to_string(bqr_link_quality_event_.buffer_overflow_bytes)
<< ", UndFlow: "
<< std::to_string(bqr_link_quality_event_.buffer_underflow_bytes);
return ss.str();
}
std::string QualityReportIdToString(uint8_t quality_report_id) {
switch (quality_report_id) {
case QUALITY_REPORT_ID_MONITOR_MODE:
return "Monitoring ";
case QUALITY_REPORT_ID_APPROACH_LSTO:
return "Appro LSTO ";
case QUALITY_REPORT_ID_A2DP_AUDIO_CHOPPY:
return "A2DP Choppy";
case QUALITY_REPORT_ID_SCO_VOICE_CHOPPY:
return "SCO Choppy ";
default:
return "Invalid ";
}
}
std::string PacketTypeToString(uint8_t packet_type) {
switch (packet_type) {
case PACKET_TYPE_ID:
return "ID";
case PACKET_TYPE_NULL:
return "NULL";
case PACKET_TYPE_POLL:
return "POLL";
case PACKET_TYPE_FHS:
return "FHS";
case PACKET_TYPE_HV1:
return "HV1";
case PACKET_TYPE_HV2:
return "HV2";
case PACKET_TYPE_HV3:
return "HV3";
case PACKET_TYPE_DV:
return "DV";
case PACKET_TYPE_EV3:
return "EV3";
case PACKET_TYPE_EV4:
return "EV4";
case PACKET_TYPE_EV5:
return "EV5";
case PACKET_TYPE_2EV3:
return "2EV3";
case PACKET_TYPE_2EV5:
return "2EV5";
case PACKET_TYPE_3EV3:
return "3EV3";
case PACKET_TYPE_3EV5:
return "3EV5";
case PACKET_TYPE_DM1:
return "DM1";
case PACKET_TYPE_DH1:
return "DH1";
case PACKET_TYPE_DM3:
return "DM3";
case PACKET_TYPE_DH3:
return "DH3";
case PACKET_TYPE_DM5:
return "DM5";
case PACKET_TYPE_DH5:
return "DH5";
case PACKET_TYPE_AUX1:
return "AUX1";
case PACKET_TYPE_2DH1:
return "2DH1";
case PACKET_TYPE_2DH3:
return "2DH3";
case PACKET_TYPE_2DH5:
return "2DH5";
case PACKET_TYPE_3DH1:
return "3DH1";
case PACKET_TYPE_3DH3:
return "3DH3";
case PACKET_TYPE_3DH5:
return "3DH5";
default:
return "UnKnown ";
}
}
void EnableBtQualityReport(bool is_enable) {
LOG(INFO) << __func__ << ": is_enable: " << logbool(is_enable);
char bqr_prop_evtmask[PROPERTY_VALUE_MAX] = {0};
char bqr_prop_interval_ms[PROPERTY_VALUE_MAX] = {0};
osi_property_get(kpPropertyEventMask, bqr_prop_evtmask, "");
osi_property_get(kpPropertyMinReportIntervalMs, bqr_prop_interval_ms, "");
if (strlen(bqr_prop_evtmask) == 0 || strlen(bqr_prop_interval_ms) == 0) {
LOG(WARNING) << __func__ << ": Bluetooth Quality Report is disabled."
<< " bqr_prop_evtmask: " << bqr_prop_evtmask
<< ", bqr_prop_interval_ms: " << bqr_prop_interval_ms;
return;
}
BqrConfiguration bqr_config = {};
if (is_enable) {
bqr_config.report_action = REPORT_ACTION_ADD;
bqr_config.quality_event_mask =
static_cast(atoi(bqr_prop_evtmask));
bqr_config.minimum_report_interval_ms =
static_cast(atoi(bqr_prop_interval_ms));
} else {
bqr_config.report_action = REPORT_ACTION_CLEAR;
bqr_config.quality_event_mask = kQualityEventMaskAllOff;
bqr_config.minimum_report_interval_ms = kMinReportIntervalNoLimit;
}
LOG(INFO) << __func__
<< ": Event Mask: " << loghex(bqr_config.quality_event_mask)
<< ", Interval: " << bqr_config.minimum_report_interval_ms;
ConfigureBqr(bqr_config);
}
void ConfigureBqr(const BqrConfiguration& bqr_config) {
if (bqr_config.report_action > REPORT_ACTION_CLEAR ||
bqr_config.quality_event_mask > kQualityEventMaskAll ||
bqr_config.minimum_report_interval_ms > kMinReportIntervalMaxMs) {
LOG(FATAL) << __func__ << ": Invalid Parameter"
<< ", Action: " << bqr_config.report_action
<< ", Mask: " << loghex(bqr_config.quality_event_mask)
<< ", Interval: " << bqr_config.minimum_report_interval_ms;
return;
}
LOG(INFO) << __func__ << ": Action: "
<< loghex(static_cast(bqr_config.report_action))
<< ", Mask: " << loghex(bqr_config.quality_event_mask)
<< ", Interval: " << bqr_config.minimum_report_interval_ms;
uint8_t param[sizeof(BqrConfiguration)];
uint8_t* p_param = param;
UINT8_TO_STREAM(p_param, bqr_config.report_action);
UINT32_TO_STREAM(p_param, bqr_config.quality_event_mask);
UINT16_TO_STREAM(p_param, bqr_config.minimum_report_interval_ms);
BTM_VendorSpecificCommand(HCI_CONTROLLER_BQR, p_param - param, param,
BqrVscCompleteCallback);
}
void BqrVscCompleteCallback(tBTM_VSC_CMPL* p_vsc_cmpl_params) {
if (p_vsc_cmpl_params->param_len < 1) {
LOG(ERROR) << __func__ << ": The length of returned parameters is less than 1";
return;
}
uint8_t* p_event_param_buf = p_vsc_cmpl_params->p_param_buf;
uint8_t status = 0xff;
// [Return Parameter] | [Size] | [Purpose]
// Status | 1 octet | Command complete status
// Current_Quality_Event_Mask | 4 octets | Indicates current bit mask setting
STREAM_TO_UINT8(status, p_event_param_buf);
if (status != HCI_SUCCESS) {
LOG(ERROR) << __func__ << ": Fail to configure BQR. status: " << loghex(status);
return;
}
if (p_vsc_cmpl_params->param_len != 5) {
LOG(FATAL) << __func__
<< ": The length of returned parameters is not equal to 5: "
<< std::to_string(p_vsc_cmpl_params->param_len);
return;
}
uint32_t current_quality_event_mask = kQualityEventMaskAllOff;
STREAM_TO_UINT32(current_quality_event_mask, p_event_param_buf);
LOG(INFO) << __func__
<< ", current event mask: " << loghex(current_quality_event_mask);
ConfigureBqrCmpl(current_quality_event_mask);
}
void ConfigureBqrCmpl(uint32_t current_evt_mask) {
LOG(INFO) << __func__ << ": current_evt_mask: " << loghex(current_evt_mask);
// (Un)Register for VSE of Bluetooth Quality Report sub event
tBTM_STATUS btm_status = BTM_BT_Quality_Report_VSE_Register(
current_evt_mask > kQualityEventMaskAllOff, CategorizeBqrEvent);
if (btm_status != BTM_SUCCESS) {
LOG(ERROR) << __func__ << ": Fail to (un)register VSE of BQR sub event."
<< " status: " << btm_status;
return;
}
if (LmpLlMessageTraceLogFd != INVALID_FD &&
(current_evt_mask & kQualityEventMaskLmpMessageTrace) == 0) {
LOG(INFO) << __func__ << ": Closing LMP/LL log file.";
close(LmpLlMessageTraceLogFd);
LmpLlMessageTraceLogFd = INVALID_FD;
}
if (BtSchedulingTraceLogFd != INVALID_FD &&
(current_evt_mask & kQualityEventMaskBtSchedulingTrace) == 0) {
LOG(INFO) << __func__ << ": Closing Scheduling log file.";
close(BtSchedulingTraceLogFd);
BtSchedulingTraceLogFd = INVALID_FD;
}
}
void CategorizeBqrEvent(uint8_t length, uint8_t* p_bqr_event) {
if (length == 0) {
LOG(WARNING) << __func__ << ": Lengths of all of the parameters are zero.";
return;
}
uint8_t quality_report_id = p_bqr_event[0];
switch (quality_report_id) {
case QUALITY_REPORT_ID_MONITOR_MODE:
case QUALITY_REPORT_ID_APPROACH_LSTO:
case QUALITY_REPORT_ID_A2DP_AUDIO_CHOPPY:
case QUALITY_REPORT_ID_SCO_VOICE_CHOPPY:
if (length < kLinkQualityParamTotalLen) {
LOG(FATAL) << __func__
<< ": Parameter total length: " << std::to_string(length)
<< " is abnormal. It shall be not shorter than: "
<< std::to_string(kLinkQualityParamTotalLen);
return;
}
AddLinkQualityEventToQueue(length, p_bqr_event);
break;
// The Root Inflammation and Log Dump related event should be handled and
// intercepted already.
case QUALITY_REPORT_ID_ROOT_INFLAMMATION:
case QUALITY_REPORT_ID_LMP_LL_MESSAGE_TRACE:
case QUALITY_REPORT_ID_BT_SCHEDULING_TRACE:
case QUALITY_REPORT_ID_CONTROLLER_DBG_INFO:
LOG(WARNING) << __func__
<< ": Unexpected ID: " << loghex(quality_report_id);
break;
default:
LOG(WARNING) << __func__ << ": Unknown ID: " << loghex(quality_report_id);
break;
}
}
void AddLinkQualityEventToQueue(uint8_t length, uint8_t* p_link_quality_event) {
std::unique_ptr p_bqr_event = std::make_unique();
p_bqr_event->ParseBqrLinkQualityEvt(length, p_link_quality_event);
LOG(WARNING) << *p_bqr_event;
invoke_link_quality_report_cb(
bluetooth::common::time_get_os_boottime_ms(),
p_bqr_event->bqr_link_quality_event_.quality_report_id,
p_bqr_event->bqr_link_quality_event_.rssi,
p_bqr_event->bqr_link_quality_event_.snr,
p_bqr_event->bqr_link_quality_event_.retransmission_count,
p_bqr_event->bqr_link_quality_event_.no_rx_count,
p_bqr_event->bqr_link_quality_event_.nak_count);
#ifdef OS_ANDROID
int ret = android::util::stats_write(
android::util::BLUETOOTH_QUALITY_REPORT_REPORTED,
p_bqr_event->bqr_link_quality_event_.quality_report_id,
p_bqr_event->bqr_link_quality_event_.packet_types,
p_bqr_event->bqr_link_quality_event_.connection_handle,
p_bqr_event->bqr_link_quality_event_.connection_role,
p_bqr_event->bqr_link_quality_event_.tx_power_level,
p_bqr_event->bqr_link_quality_event_.rssi,
p_bqr_event->bqr_link_quality_event_.snr,
p_bqr_event->bqr_link_quality_event_.unused_afh_channel_count,
p_bqr_event->bqr_link_quality_event_.afh_select_unideal_channel_count,
p_bqr_event->bqr_link_quality_event_.lsto,
p_bqr_event->bqr_link_quality_event_.connection_piconet_clock,
p_bqr_event->bqr_link_quality_event_.retransmission_count,
p_bqr_event->bqr_link_quality_event_.no_rx_count,
p_bqr_event->bqr_link_quality_event_.nak_count,
p_bqr_event->bqr_link_quality_event_.last_tx_ack_timestamp,
p_bqr_event->bqr_link_quality_event_.flow_off_count,
p_bqr_event->bqr_link_quality_event_.last_flow_on_timestamp,
p_bqr_event->bqr_link_quality_event_.buffer_overflow_bytes,
p_bqr_event->bqr_link_quality_event_.buffer_underflow_bytes);
if (ret < 0) {
LOG(WARNING) << __func__ << ": failed to log BQR event to statsd, error "
<< ret;
}
#else
// TODO(abps) Metrics for non-Android build
#endif
kpBqrEventQueue->Enqueue(p_bqr_event.release());
}
void DumpLmpLlMessage(uint8_t length, uint8_t* p_lmp_ll_message_event) {
std::unique_ptr p_bqr_event = std::make_unique();
if (LmpLlMessageTraceLogFd == INVALID_FD ||
LmpLlMessageTraceCounter >= kLogDumpEventPerFile) {
LmpLlMessageTraceLogFd = OpenLmpLlTraceLogFile();
}
if (LmpLlMessageTraceLogFd != INVALID_FD) {
p_bqr_event->WriteLmpLlTraceLogFile(LmpLlMessageTraceLogFd, length,
p_lmp_ll_message_event);
}
}
int OpenLmpLlTraceLogFile() {
if (rename(kpLmpLlMessageTraceLogPath, kpLmpLlMessageTraceLastLogPath) != 0 &&
errno != ENOENT) {
LOG(ERROR) << __func__ << ": Unable to rename '"
<< kpLmpLlMessageTraceLogPath << "' to '"
<< kpLmpLlMessageTraceLastLogPath << "' : " << strerror(errno);
}
mode_t prevmask = umask(0);
int logfile_fd =
open(kpLmpLlMessageTraceLogPath, O_WRONLY | O_CREAT | O_TRUNC,
S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP | S_IROTH);
umask(prevmask);
if (logfile_fd == INVALID_FD) {
LOG(ERROR) << __func__ << ": Unable to open '" << kpLmpLlMessageTraceLogPath
<< "' : " << strerror(errno);
} else {
LmpLlMessageTraceCounter = 0;
}
return logfile_fd;
}
void DumpBtScheduling(uint8_t length, uint8_t* p_bt_scheduling_event) {
std::unique_ptr p_bqr_event = std::make_unique();
if (BtSchedulingTraceLogFd == INVALID_FD ||
BtSchedulingTraceCounter == kLogDumpEventPerFile) {
BtSchedulingTraceLogFd = OpenBtSchedulingTraceLogFile();
}
if (BtSchedulingTraceLogFd != INVALID_FD) {
p_bqr_event->WriteBtSchedulingTraceLogFile(BtSchedulingTraceLogFd, length,
p_bt_scheduling_event);
}
}
int OpenBtSchedulingTraceLogFile() {
if (rename(kpBtSchedulingTraceLogPath, kpBtSchedulingTraceLastLogPath) != 0 &&
errno != ENOENT) {
LOG(ERROR) << __func__ << ": Unable to rename '"
<< kpBtSchedulingTraceLogPath << "' to '"
<< kpBtSchedulingTraceLastLogPath << "' : " << strerror(errno);
}
mode_t prevmask = umask(0);
int logfile_fd =
open(kpBtSchedulingTraceLogPath, O_WRONLY | O_CREAT | O_TRUNC,
S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP | S_IROTH);
umask(prevmask);
if (logfile_fd == INVALID_FD) {
LOG(ERROR) << __func__ << ": Unable to open '" << kpBtSchedulingTraceLogPath
<< "' : " << strerror(errno);
} else {
BtSchedulingTraceCounter = 0;
}
return logfile_fd;
}
void DebugDump(int fd) {
dprintf(fd, "\nBT Quality Report Events: \n");
if (kpBqrEventQueue->Empty()) {
dprintf(fd, "Event queue is empty.\n");
return;
}
while (!kpBqrEventQueue->Empty()) {
std::unique_ptr p_event(kpBqrEventQueue->Dequeue());
bool warning = (p_event->bqr_link_quality_event_.rssi < kCriWarnRssi ||
p_event->bqr_link_quality_event_.unused_afh_channel_count >
kCriWarnUnusedCh);
std::stringstream ss_timestamp;
ss_timestamp << std::put_time(&p_event->tm_timestamp_, "%m-%d %H:%M:%S");
dprintf(fd, "%c %s %s\n", warning ? '*' : ' ', ss_timestamp.str().c_str(),
p_event->ToString().c_str());
}
dprintf(fd, "\n");
}
} // namespace bqr
} // namespace bluetooth