diff options
author | 2025-02-07 17:48:44 -0800 | |
---|---|---|
committer | 2025-03-10 11:26:52 -0700 | |
commit | 59e9fa67a1ec68ade816a84d161dc4da93c7419f (patch) | |
tree | 38c6d37813783c039d95cace6afb25c61a323a4f /system | |
parent | ff22be65bf8163fd8749d1b57d8b47e3eaf807db (diff) |
Add metrics logging for Bluetooth offload socket
Bug: 399022276
Flag: EXEMPT, metrics update
Test: m com.google.android.bt
Test: Android Data Hub Atom Tester
Change-Id: Ib5a4a0d6970287388851bcf5fdb71121e3092b76
Diffstat (limited to 'system')
-rw-r--r-- | system/btif/include/btif_metrics_logging.h | 5 | ||||
-rw-r--r-- | system/btif/include/btif_sock_logging.h | 4 | ||||
-rw-r--r-- | system/btif/src/btif_metrics_logging.cc | 10 | ||||
-rw-r--r-- | system/btif/src/btif_sock.cc | 15 | ||||
-rw-r--r-- | system/btif/src/btif_sock_l2cap.cc | 118 | ||||
-rw-r--r-- | system/btif/src/btif_sock_logging.cc | 66 | ||||
-rw-r--r-- | system/btif/src/btif_sock_rfc.cc | 89 | ||||
-rw-r--r-- | system/common/metrics.cc | 18 | ||||
-rw-r--r-- | system/common/metrics.h | 8 | ||||
-rw-r--r-- | system/common/metrics_linux.cc | 5 | ||||
-rw-r--r-- | system/gd/os/android/metrics.cc | 19 | ||||
-rw-r--r-- | system/gd/os/chromeos/metrics.cc | 5 | ||||
-rw-r--r-- | system/gd/os/host/metrics.cc | 3 | ||||
-rw-r--r-- | system/gd/os/linux/metrics.cc | 5 | ||||
-rw-r--r-- | system/gd/os/metrics.h | 8 | ||||
-rw-r--r-- | system/include/hardware/bt_sock.h | 19 | ||||
-rw-r--r-- | system/main/shim/metrics_api.cc | 10 | ||||
-rw-r--r-- | system/main/shim/metrics_api.h | 8 | ||||
-rw-r--r-- | system/test/mock/mock_main_shim_metrics_api.cc | 7 | ||||
-rw-r--r-- | system/test/mock/mock_main_shim_metrics_api.h | 14 |
20 files changed, 306 insertions, 130 deletions
diff --git a/system/btif/include/btif_metrics_logging.h b/system/btif/include/btif_metrics_logging.h index d68eddce5e..94f7a66b79 100644 --- a/system/btif/include/btif_metrics_logging.h +++ b/system/btif/include/btif_metrics_logging.h @@ -52,7 +52,10 @@ void log_counter_metrics_btif(android::bluetooth::CodePathCounterKeyEnum key, in void log_socket_connection_state(const RawAddress& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role); + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload); bool init_metric_id_allocator(const std::unordered_map<RawAddress, int>& paired_device_map, bluetooth::shim::CallbackLegacy save_id_callback, diff --git a/system/btif/include/btif_sock_logging.h b/system/btif/include/btif_sock_logging.h index 7cd30f6396..38dfe3e302 100644 --- a/system/btif/include/btif_sock_logging.h +++ b/system/btif/include/btif_sock_logging.h @@ -16,9 +16,11 @@ #pragma once +#include "hardware/bt_sock.h" #include "types/raw_address.h" void btif_sock_connection_logger(const RawAddress& address, int port, int type, int state, int role, int uid, int server_port, int64_t tx_bytes, int64_t rx_bytes, - const char* server_name); + const char* server_name, uint64_t connection_start_time_ms, + btsock_error_code_t error_code, btsock_data_path_t data_path); void btif_sock_dump(int fd); diff --git a/system/btif/src/btif_metrics_logging.cc b/system/btif/src/btif_metrics_logging.cc index e116cebe28..40f2fed315 100644 --- a/system/btif/src/btif_metrics_logging.cc +++ b/system/btif/src/btif_metrics_logging.cc @@ -72,9 +72,13 @@ void log_read_tx_power_level_result(const RawAddress& address, uint16_t handle, void log_socket_connection_state(const RawAddress& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) { - bluetooth::shim::LogMetricSocketConnectionState(address, port, type, connection_state, tx_bytes, - rx_bytes, uid, server_port, socket_role); + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload) { + bluetooth::shim::LogMetricSocketConnectionState( + address, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, socket_role, + connection_duration_ms, error_code, is_hardware_offload); } void log_counter_metrics_btif(android::bluetooth::CodePathCounterKeyEnum key, int64_t value) { diff --git a/system/btif/src/btif_sock.cc b/system/btif/src/btif_sock.cc index d58326e571..dae8f745c2 100644 --- a/system/btif/src/btif_sock.cc +++ b/system/btif/src/btif_sock.cc @@ -177,7 +177,8 @@ static bt_status_t btsock_listen(btsock_type_t type, const char* service_name, RawAddress::kEmpty, type, channel, app_uid, data_path, hub_id, endpoint_id, max_rx_packet_size); btif_sock_connection_logger(RawAddress::kEmpty, 0, type, SOCKET_CONNECTION_STATE_LISTENING, - SOCKET_ROLE_LISTEN, app_uid, channel, 0, 0, service_name); + SOCKET_ROLE_LISTEN, app_uid, channel, 0, 0, service_name, 0, + BTSOCK_ERROR_NONE, data_path); switch (type) { case BTSOCK_RFCOMM: status = btsock_rfc_listen(service_name, service_uuid, channel, sock_fd, flags, app_uid, @@ -207,7 +208,8 @@ static bt_status_t btsock_listen(btsock_type_t type, const char* service_name, "channel: {}, app_uid: {}", RawAddress::kEmpty, type, channel, app_uid); btif_sock_connection_logger(RawAddress::kEmpty, 0, type, SOCKET_CONNECTION_STATE_DISCONNECTED, - SOCKET_ROLE_LISTEN, app_uid, channel, 0, 0, service_name); + SOCKET_ROLE_LISTEN, app_uid, channel, 0, 0, service_name, 0, + BTSOCK_ERROR_LISTEN_FAILURE, data_path); } return status; } @@ -227,9 +229,9 @@ static bt_status_t btsock_connect(const RawAddress* bd_addr, btsock_type_t type, *sock_fd = INVALID_FD; bt_status_t status = BT_STATUS_SOCKET_ERROR; - btif_sock_connection_logger(*bd_addr, 0, type, SOCKET_CONNECTION_STATE_CONNECTING, - SOCKET_ROLE_CONNECTION, app_uid, channel, 0, 0, - uuid ? uuid->ToString().c_str() : ""); + btif_sock_connection_logger( + *bd_addr, 0, type, SOCKET_CONNECTION_STATE_CONNECTING, SOCKET_ROLE_CONNECTION, app_uid, + channel, 0, 0, uuid ? uuid->ToString().c_str() : "", 0, BTSOCK_ERROR_NONE, data_path); switch (type) { case BTSOCK_RFCOMM: status = btsock_rfc_connect(bd_addr, uuid, channel, sock_fd, flags, app_uid, data_path, @@ -261,7 +263,8 @@ static bt_status_t btsock_connect(const RawAddress* bd_addr, btsock_type_t type, *bd_addr, type, channel, app_uid); btif_sock_connection_logger(*bd_addr, 0, type, SOCKET_CONNECTION_STATE_DISCONNECTED, SOCKET_ROLE_CONNECTION, app_uid, channel, 0, 0, - uuid ? uuid->ToString().c_str() : ""); + uuid ? uuid->ToString().c_str() : "", 0, + BTSOCK_ERROR_CONNECTION_FAILURE, data_path); } return status; } diff --git a/system/btif/src/btif_sock_l2cap.cc b/system/btif/src/btif_sock_l2cap.cc index d607ff3b74..3867727cdb 100644 --- a/system/btif/src/btif_sock_l2cap.cc +++ b/system/btif/src/btif_sock_l2cap.cc @@ -35,6 +35,7 @@ #include "btif/include/btif_sock_thread.h" #include "btif/include/btif_sock_util.h" #include "btif/include/btif_uid.h" +#include "common/time_util.h" #include "gd/os/rand.h" #include "include/hardware/bluetooth.h" #include "internal_include/bt_target.h" @@ -92,6 +93,7 @@ typedef struct l2cap_socket { uint64_t hub_id; // ID of the hub to which the end point belongs uint64_t endpoint_id; // ID of the hub end point bool is_accepting; // is app accepting on server socket? + uint64_t connection_start_time_ms; // Timestamp when the connection state started } l2cap_socket; static void btsock_l2cap_server_listen(l2cap_socket* sock); @@ -238,7 +240,7 @@ static l2cap_socket* btsock_l2cap_find_by_conn_uuid_l(Uuid& conn_uuid) { return nullptr; } -static void btsock_l2cap_free_l(l2cap_socket* sock) { +static void btsock_l2cap_free_l(l2cap_socket* sock, btsock_error_code_t error_code) { uint8_t* buf; l2cap_socket* t = socks; @@ -258,7 +260,8 @@ static void btsock_l2cap_free_l(l2cap_socket* sock) { sock->addr, sock->id, sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, SOCKET_CONNECTION_STATE_DISCONNECTED, sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, sock->app_uid, sock->channel, - sock->tx_bytes, sock->rx_bytes, sock->name); + sock->tx_bytes, sock->rx_bytes, sock->name, sock->connection_start_time_ms, error_code, + sock->data_path); if (com::android::bluetooth::flags::socket_settings_api()) { if (sock->data_path == BTSOCK_DATA_PATH_HARDWARE_OFFLOAD && !sock->server && sock->socket_id != 0) { @@ -359,6 +362,7 @@ static l2cap_socket* btsock_l2cap_alloc_l(const char* name, const RawAddress* ad sock->hub_id = 0; sock->endpoint_id = 0; sock->is_accepting = false; + sock->connection_start_time_ms = 0; if (name) { strncpy(sock->name, name, sizeof(sock->name) - 1); @@ -418,7 +422,7 @@ bt_status_t btsock_l2cap_cleanup() { std::unique_lock<std::mutex> lock(state_lock); pth = -1; while (socks) { - btsock_l2cap_free_l(socks); + btsock_l2cap_free_l(socks, BTSOCK_ERROR_NONE); } return BT_STATUS_SUCCESS; } @@ -500,7 +504,7 @@ static void on_srv_l2cap_listen_started(tBTA_JV_L2CAP_START* p_start, uint32_t i if (p_start->status != tBTA_JV_STATUS::SUCCESS) { log::error("Unable to start l2cap server socket_id:{}", sock->id); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_SERVER_START_FAILURE); return; } @@ -510,17 +514,17 @@ static void on_srv_l2cap_listen_started(tBTA_JV_L2CAP_START* p_start, uint32_t i "Listening for L2CAP connection for device: {}, channel: {}, app_uid: " "{}, id: {}, is_le: {}", sock->addr, sock->channel, sock->app_uid, sock->id, sock->is_le_coc); - btif_sock_connection_logger(sock->addr, sock->id, - sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_LISTENING, - sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - sock->app_uid, sock->channel, 0, 0, sock->name); + btif_sock_connection_logger( + sock->addr, sock->id, sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_LISTENING, + sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, sock->app_uid, sock->channel, + 0, 0, sock->name, 0, BTSOCK_ERROR_NONE, sock->data_path); if (!sock->server_psm_sent) { if (!send_app_psm_or_chan_l(sock)) { // closed log::info("Unable to send socket to application socket_id:{}", sock->id); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_SEND_TO_APP_FAILURE); } else { sock->server_psm_sent = true; } @@ -539,7 +543,7 @@ static void on_cl_l2cap_init(tBTA_JV_L2CAP_CL_INIT* p_init, uint32_t id) { if (p_init->status != tBTA_JV_STATUS::SUCCESS) { log::error("Initialization status failed socket_id:{}", id); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_CLIENT_INIT_FAILURE); return; } @@ -589,11 +593,12 @@ static void on_srv_l2cap_psm_connect_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap_socket* "id: {}, is_le: {}, socket_id: {}, rx_mtu: {}", accept_rs->addr, accept_rs->channel, accept_rs->app_uid, accept_rs->id, accept_rs->is_le_coc, accept_rs->socket_id, accept_rs->rx_mtu); - btif_sock_connection_logger(accept_rs->addr, accept_rs->id, - accept_rs->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_CONNECTED, - accept_rs->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - accept_rs->app_uid, accept_rs->channel, 0, 0, accept_rs->name); + btif_sock_connection_logger( + accept_rs->addr, accept_rs->id, accept_rs->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_CONNECTED, + accept_rs->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, accept_rs->app_uid, + accept_rs->channel, 0, 0, accept_rs->name, 0, BTSOCK_ERROR_NONE, accept_rs->data_path); + accept_rs->connection_start_time_ms = common::time_gettimeofday_us() / 1000; // start monitor the socket btsock_thread_add_fd(pth, sock->our_fd, BTSOCK_L2CAP, SOCK_THREAD_FD_EXCEPTION, sock->id); @@ -638,11 +643,12 @@ static void on_cl_l2cap_psm_connect_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap_socket* "id: {}, is_le: {}, socket_id: {}, rx_mtu: {}", sock->addr, sock->channel, sock->app_uid, sock->id, sock->is_le_coc, sock->socket_id, sock->rx_mtu); - btif_sock_connection_logger(sock->addr, sock->id, - sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_CONNECTED, - sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - sock->app_uid, sock->channel, 0, 0, sock->name); + btif_sock_connection_logger( + sock->addr, sock->id, sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_CONNECTED, + sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, sock->app_uid, sock->channel, + 0, 0, sock->name, 0, BTSOCK_ERROR_NONE, sock->data_path); + sock->connection_start_time_ms = common::time_gettimeofday_us() / 1000; // start monitoring the socketpair to get call back when app writing data btsock_thread_add_fd(pth, sock->our_fd, BTSOCK_L2CAP, SOCK_THREAD_FD_RD, sock->id); @@ -679,7 +685,7 @@ static void on_l2cap_connect(tBTA_JV* p_data, uint32_t id) { } } else { log::error("Unable to open socket after receiving connection socket_id:{}", sock->id); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_OPEN_FAILURE); } } @@ -697,11 +703,11 @@ static void on_l2cap_close(tBTA_JV_L2CAP_CLOSE* p_close, uint32_t id) { "Disconnecting from L2CAP connection for device: {}, channel: {}, " "app_uid: {}, id: {}, is_le: {}", sock->addr, sock->channel, sock->app_uid, sock->id, sock->is_le_coc); - btif_sock_connection_logger(sock->addr, sock->id, - sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_DISCONNECTING, - sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - sock->app_uid, sock->channel, 0, 0, sock->name); + btif_sock_connection_logger( + sock->addr, sock->id, sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_DISCONNECTING, + sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, sock->app_uid, sock->channel, + 0, 0, sock->name, 0, BTSOCK_ERROR_NONE, sock->data_path); if (com::android::bluetooth::flags::donot_push_error_code_to_app_when_connected()) { if (!sock->connected) { if (!send_app_err_code(sock, p_close->reason)) { @@ -720,7 +726,7 @@ static void on_l2cap_close(tBTA_JV_L2CAP_CLOSE* p_close, uint32_t id) { if (sock->server) { BTA_JvFreeChannel(sock->channel, tBTA_JV_CONN_TYPE::L2CAP); } - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_NONE); } static void on_l2cap_outgoing_congest(tBTA_JV_L2CAP_CONG* p, uint32_t id) { @@ -786,7 +792,7 @@ static void on_l2cap_data_ind(tBTA_JV* /* evt */, uint32_t id) { } else { // connection must be dropped log::warn("Closing socket as unable to push data to socket socket_id:{}", sock->id); BTA_JvL2capClose(sock->handle); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_RECEIVE_DATA_FAILURE); return; } } @@ -1151,6 +1157,7 @@ static bool btsock_l2cap_read_signaled_on_listen_socket(int fd, int /* flags */, static void btsock_l2cap_signaled_flagged(int fd, int flags, uint32_t user_id) { char drop_it = false; + btsock_error_code_t error_code = BTSOCK_ERROR_NONE; /* We use MSG_DONTWAIT when sending data to JAVA, hence it can be accepted to * hold the lock. */ @@ -1163,11 +1170,13 @@ static void btsock_l2cap_signaled_flagged(int fd, int flags, uint32_t user_id) { if (!sock->server) { // app sending data on connection socket if (!btsock_l2cap_read_signaled_on_connected_socket(fd, flags, user_id, sock)) { + error_code = BTSOCK_ERROR_READ_SIGNALED_FAILURE; drop_it = true; } } else { // app sending signal on listen socket if (!btsock_l2cap_read_signaled_on_listen_socket(fd, flags, user_id, sock)) { + error_code = BTSOCK_ERROR_READ_SIGNALED_FAILURE; drop_it = true; } } @@ -1181,7 +1190,7 @@ static void btsock_l2cap_signaled_flagged(int fd, int flags, uint32_t user_id) { if (drop_it || (flags & SOCK_THREAD_FD_EXCEPTION)) { int size = 0; if (drop_it || ioctl(sock->our_fd, FIONREAD, &size) != 0 || size == 0) { - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, error_code); } } } @@ -1192,6 +1201,7 @@ void btsock_l2cap_signaled(int fd, int flags, uint32_t user_id) { return; } char drop_it = false; + btsock_error_code_t error_code = BTSOCK_ERROR_NONE; /* We use MSG_DONTWAIT when sending data to JAVA, hence it can be accepted to * hold the lock. */ @@ -1238,6 +1248,7 @@ void btsock_l2cap_signaled(int fd, int flags, uint32_t user_id) { BTA_JvL2capWrite(sock->handle, PTR_TO_UINT(buffer), buffer, user_id); } } else { + error_code = BTSOCK_ERROR_READ_SIGNALED_FAILURE; drop_it = true; } } @@ -1250,7 +1261,7 @@ void btsock_l2cap_signaled(int fd, int flags, uint32_t user_id) { if (drop_it || (flags & SOCK_THREAD_FD_EXCEPTION)) { int size = 0; if (drop_it || ioctl(sock->our_fd, FIONREAD, &size) != 0 || size == 0) { - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, error_code); } } } @@ -1269,7 +1280,7 @@ bt_status_t btsock_l2cap_disconnect(const RawAddress* bd_addr) { while (sock) { l2cap_socket* next = sock->next; if (sock->addr == *bd_addr) { - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_NONE); } sock = next; } @@ -1343,7 +1354,7 @@ void on_btsocket_l2cap_opened_complete(uint64_t socket_id, bool success) { } if (!success) { log::error("L2CAP opened complete failed with socket_id:{}", socket_id); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_OPEN_FAILURE); return; } // If the socket was accepted from listen socket, use listen_fd. @@ -1368,11 +1379,12 @@ void on_btsocket_l2cap_opened_complete(uint64_t socket_id, bool success) { "is_le: {}, socket_id: {}, rx_mtu: {}", sock->addr, sock->channel, sock->app_uid, sock->id, sock->is_le_coc, sock->socket_id, sock->rx_mtu); - btif_sock_connection_logger(sock->addr, sock->id, - sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_CONNECTED, - sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - sock->app_uid, sock->channel, 0, 0, sock->name); + btif_sock_connection_logger( + sock->addr, sock->id, sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_CONNECTED, + sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, sock->app_uid, + sock->channel, 0, 0, sock->name, 0, BTSOCK_ERROR_NONE, sock->data_path); + sock->connection_start_time_ms = common::time_gettimeofday_us() / 1000; log::info("Connected l2cap socket socket_id:{}", sock->id); sock->connected = true; @@ -1389,7 +1401,7 @@ void on_btsocket_l2cap_close(uint64_t socket_id) { return; } log::info("L2CAP close request for socket_id:{}", socket_id); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_NONE); } static void on_cl_l2cap_psm_connect_offload_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap_socket* sock) { @@ -1407,11 +1419,12 @@ static void on_cl_l2cap_psm_connect_offload_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap_ "id: {}, is_le: {}, socket_id: {}, rx_mtu: {}", sock->addr, sock->channel, sock->app_uid, sock->id, sock->is_le_coc, sock->socket_id, sock->rx_mtu); - btif_sock_connection_logger(sock->addr, sock->id, - sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_CONNECTED, - sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - sock->app_uid, sock->channel, 0, 0, sock->name); + btif_sock_connection_logger( + sock->addr, sock->id, sock->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_CONNECTED, + sock->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, sock->app_uid, sock->channel, + 0, 0, sock->name, 0, BTSOCK_ERROR_NONE, sock->data_path); + sock->connection_start_time_ms = common::time_gettimeofday_us() / 1000; bluetooth::hal::SocketContext socket_context = { .socket_id = sock->socket_id, @@ -1426,7 +1439,7 @@ static void on_cl_l2cap_psm_connect_offload_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap_ }; if (!bluetooth::shim::GetLppOffloadManager()->SocketOpened(socket_context)) { log::warn("L2CAP socket opened failed. Disconnect the incoming connection."); - btsock_l2cap_free_l(sock); + btsock_l2cap_free_l(sock, BTSOCK_ERROR_OFFLOAD_HAL_OPEN_FAILURE); } else { log::info( "L2CAP socket opened successful. Will send connect signal in " @@ -1470,11 +1483,12 @@ static void on_srv_l2cap_psm_connect_offload_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap "id: {}, is_le: {}, socket_id: {}, rx_mtu: {}", accept_rs->addr, accept_rs->channel, accept_rs->app_uid, accept_rs->id, accept_rs->is_le_coc, accept_rs->socket_id, accept_rs->rx_mtu); - btif_sock_connection_logger(accept_rs->addr, accept_rs->id, - accept_rs->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, - SOCKET_CONNECTION_STATE_CONNECTED, - accept_rs->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - accept_rs->app_uid, accept_rs->channel, 0, 0, accept_rs->name); + btif_sock_connection_logger( + accept_rs->addr, accept_rs->id, accept_rs->is_le_coc ? BTSOCK_L2CAP_LE : BTSOCK_L2CAP, + SOCKET_CONNECTION_STATE_CONNECTED, + accept_rs->server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, accept_rs->app_uid, + accept_rs->channel, 0, 0, accept_rs->name, 0, BTSOCK_ERROR_NONE, accept_rs->data_path); + accept_rs->connection_start_time_ms = common::time_gettimeofday_us() / 1000; bluetooth::hal::SocketContext socket_context = { .socket_id = accept_rs->socket_id, @@ -1489,10 +1503,10 @@ static void on_srv_l2cap_psm_connect_offload_l(tBTA_JV_L2CAP_OPEN* p_open, l2cap }; if (!sock->is_accepting) { log::warn("Server socket is not accepting. Disconnect the incoming connection."); - btsock_l2cap_free_l(accept_rs); + btsock_l2cap_free_l(accept_rs, BTSOCK_ERROR_OFFLOAD_SERVER_NOT_ACCEPTING); } else if (!bluetooth::shim::GetLppOffloadManager()->SocketOpened(socket_context)) { log::warn("L2CAP socket opened failed. Disconnect the incoming connection."); - btsock_l2cap_free_l(accept_rs); + btsock_l2cap_free_l(accept_rs, BTSOCK_ERROR_OFFLOAD_HAL_OPEN_FAILURE); } else { log::info("L2CAP socket opened successful. Will send connect signal in async callback."); } diff --git a/system/btif/src/btif_sock_logging.cc b/system/btif/src/btif_sock_logging.cc index acb38f7de5..111e52002b 100644 --- a/system/btif/src/btif_sock_logging.cc +++ b/system/btif/src/btif_sock_logging.cc @@ -25,6 +25,7 @@ #include "btif/include/btif_metrics_logging.h" #include "btif/include/btif_sock.h" +#include "common/time_util.h" #include "types/raw_address.h" #define SOCK_LOGGER_SIZE_MAX 16 @@ -50,11 +51,15 @@ static SockConnectionEvent connection_logger[SOCK_LOGGER_SIZE_MAX]; static android::bluetooth::SocketConnectionstateEnum toConnectionStateEnum(int state); static android::bluetooth::SocketRoleEnum toSocketRoleEnum(int role); +static android::bluetooth::SocketErrorEnum toSocketErrorEnum(btsock_error_code_t error_code); +static uint64_t getConnectionDuration(uint64_t start_time_ms); void btif_sock_connection_logger(const RawAddress& address, int port, int type, int state, int role, int uid, int server_port, int64_t tx_bytes, int64_t rx_bytes, - const char* server_name) { - log::verbose("bd_addr: {}, port: {}, role: {}, state: {}", address, port, role, state); + const char* server_name, uint64_t connection_start_time_ms, + btsock_error_code_t error_code, btsock_data_path_t data_path) { + log::verbose("bd_addr: {}, port: {}, role: {}, state: {}, data_path: {}", address, port, role, + state, data_path); uint8_t index = logger_index++ % SOCK_LOGGER_SIZE_MAX; @@ -74,8 +79,10 @@ void btif_sock_connection_logger(const RawAddress& address, int port, int type, } clock_gettime(CLOCK_REALTIME, &connection_logger[index].timestamp); - log_socket_connection_state(address, port, type, toConnectionStateEnum(state), tx_bytes, rx_bytes, - uid, server_port, toSocketRoleEnum(role)); + log_socket_connection_state( + address, port, type, toConnectionStateEnum(state), tx_bytes, rx_bytes, uid, server_port, + toSocketRoleEnum(role), getConnectionDuration(connection_start_time_ms), + toSocketErrorEnum(error_code), data_path == BTSOCK_DATA_PATH_HARDWARE_OFFLOAD); } void btif_sock_dump(int fd) { @@ -192,3 +199,54 @@ static android::bluetooth::SocketRoleEnum toSocketRoleEnum(int role) { } return android::bluetooth::SOCKET_ROLE_UNKNOWN; } + +static android::bluetooth::SocketErrorEnum toSocketErrorEnum(btsock_error_code_t error_code) { + switch (error_code) { + case BTSOCK_ERROR_NONE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_NONE; + case BTSOCK_ERROR_SERVER_START_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_SERVER_START_FAILURE; + case BTSOCK_ERROR_CLIENT_INIT_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_CLIENT_INIT_FAILURE; + case BTSOCK_ERROR_LISTEN_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_LISTEN_FAILURE; + case BTSOCK_ERROR_CONNECTION_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_CONNECTION_FAILURE; + case BTSOCK_ERROR_OPEN_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_OPEN_FAILURE; + case BTSOCK_ERROR_OFFLOAD_SERVER_NOT_ACCEPTING: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_OFFLOAD_SERVER_NOT_ACCEPTING; + case BTSOCK_ERROR_OFFLOAD_HAL_OPEN_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_OFFLOAD_HAL_OPEN_FAILURE; + case BTSOCK_ERROR_SEND_TO_APP_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_SEND_TO_APP_FAILURE; + case BTSOCK_ERROR_RECEIVE_DATA_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_RECEIVE_DATA_FAILURE; + case BTSOCK_ERROR_READ_SIGNALED_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_READ_SIGNALED_FAILURE; + case BTSOCK_ERROR_WRITE_SIGNALED_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_WRITE_SIGNALED_FAILURE; + case BTSOCK_ERROR_SEND_SCN_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_SEND_SCN_FAILURE; + case BTSOCK_ERROR_SCN_ALLOCATION_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_SCN_ALLOCATION_FAILURE; + case BTSOCK_ERROR_ADD_SDP_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_ADD_SDP_FAILURE; + case BTSOCK_ERROR_SDP_DISCOVERY_FAILURE: + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_SDP_DISCOVERY_FAILURE; + } + return android::bluetooth::SocketErrorEnum::SOCKET_ERROR_NONE; +} + +static uint64_t getConnectionDuration(uint64_t start_time_ms) { + // start time is 0 before the connection state, use 0 for duration + if (start_time_ms == 0) { + return 0; + } + uint64_t current_time_ms = common::time_gettimeofday_us() / 1000; + if (current_time_ms <= start_time_ms) { + log::warn("Socket connection end time is not greater than start time, logging 0 ms instead"); + return 0; + } + return current_time_ms - start_time_ms; +} diff --git a/system/btif/src/btif_sock_rfc.cc b/system/btif/src/btif_sock_rfc.cc index 929ce8a3cc..4c75b0f355 100644 --- a/system/btif/src/btif_sock_rfc.cc +++ b/system/btif/src/btif_sock_rfc.cc @@ -106,6 +106,7 @@ typedef struct { uint64_t hub_id; // ID of the hub to which the end point belongs uint64_t endpoint_id; // ID of the hub end point bool is_accepting; // is app accepting on server socket? + uint64_t connection_start_time_ms; // Timestamp when the connection state started } rfc_slot_t; static rfc_slot_t rfc_slots[MAX_RFC_CHANNEL]; @@ -115,7 +116,7 @@ static std::recursive_mutex slot_lock; static uid_set_t* uid_set = NULL; static rfc_slot_t* find_free_slot(void); -static void cleanup_rfc_slot(rfc_slot_t* rs); +static void cleanup_rfc_slot(rfc_slot_t* rs, btsock_error_code_t error_code); static void jv_dm_cback(tBTA_JV_EVT event, tBTA_JV* p_data, uint32_t id); static uint32_t rfcomm_cback(tBTA_JV_EVT event, tBTA_JV* p_data, uint32_t rfcomm_slot_id); static bool send_app_scn(rfc_slot_t* rs); @@ -152,7 +153,7 @@ void btsock_rfc_cleanup(void) { std::unique_lock<std::recursive_mutex> lock(slot_lock); for (size_t i = 0; i < ARRAY_SIZE(rfc_slots); ++i) { if (rfc_slots[i].id) { - cleanup_rfc_slot(&rfc_slots[i]); + cleanup_rfc_slot(&rfc_slots[i], BTSOCK_ERROR_NONE); } list_free(rfc_slots[i].incoming_queue); rfc_slots[i].incoming_queue = NULL; @@ -251,6 +252,7 @@ static rfc_slot_t* alloc_rfc_slot(const RawAddress* addr, const char* name, cons slot->hub_id = 0; slot->endpoint_id = 0; slot->is_accepting = false; + slot->connection_start_time_ms = 0; slot->is_service_uuid_valid = !uuid.IsEmpty(); slot->service_uuid = uuid; @@ -466,13 +468,13 @@ bt_status_t btsock_rfc_connect(const RawAddress* bd_addr, const Uuid* service_uu if (ret != tBTA_JV_STATUS::SUCCESS) { log::error("unable to initiate RFCOMM connection. status:{}, scn:{}, bd_addr:{}", bta_jv_status_text(ret), slot->scn, slot->addr); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_CONNECTION_FAILURE); return BT_STATUS_SOCKET_ERROR; } if (!send_app_scn(slot)) { log::error("send_app_scn() failed, closing slot_id:{}", slot->id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_SEND_SCN_FAILURE); return BT_STATUS_SOCKET_ERROR; } } else { @@ -535,7 +537,7 @@ static void free_rfc_slot_scn(rfc_slot_t* slot) { slot->scn = 0; } -static void cleanup_rfc_slot(rfc_slot_t* slot) { +static void cleanup_rfc_slot(rfc_slot_t* slot, btsock_error_code_t error_code) { if (slot->fd != INVALID_FD) { shutdown(slot->fd, SHUT_RDWR); close(slot->fd); @@ -547,7 +549,8 @@ static void cleanup_rfc_slot(rfc_slot_t* slot) { slot->addr, slot->id, BTSOCK_RFCOMM, SOCKET_CONNECTION_STATE_DISCONNECTED, slot->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, slot->app_uid, slot->scn, slot->tx_bytes, slot->rx_bytes, - slot->role ? slot->service_name : slot->service_uuid.ToString().c_str()); + slot->role ? slot->service_name : slot->service_uuid.ToString().c_str(), + slot->connection_start_time_ms, error_code, slot->data_path); slot->fd = INVALID_FD; @@ -625,7 +628,7 @@ static void on_cl_rfc_init(tBTA_JV_RFCOMM_CL_INIT* p_init, uint32_t id) { } else if (p_init->status != tBTA_JV_STATUS::SUCCESS) { log::warn("INIT unsuccessful, status {}. Cleaning up slot_id {}", bta_jv_status_text(p_init->status), slot->id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_CLIENT_INIT_FAILURE); } else { slot->rfc_handle = p_init->handle; } @@ -640,7 +643,7 @@ static void on_srv_rfc_listen_started(tBTA_JV_RFCOMM_START* p_start, uint32_t id } else if (p_start->status != tBTA_JV_STATUS::SUCCESS) { log::warn("START unsuccessful, status {}. Cleaning up slot_id {}", bta_jv_status_text(p_start->status), slot->id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_SERVER_START_FAILURE); return; } @@ -649,10 +652,10 @@ static void on_srv_rfc_listen_started(tBTA_JV_RFCOMM_START* p_start, uint32_t id "listening for RFCOMM socket connections for device: {}, scn: {}, " "app_uid: {}, id: {}", slot->addr, slot->scn, slot->app_uid, id); - btif_sock_connection_logger(slot->addr, slot->id, BTSOCK_RFCOMM, - SOCKET_CONNECTION_STATE_LISTENING, - slot->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - slot->app_uid, slot->scn, 0, 0, slot->service_name); + btif_sock_connection_logger( + slot->addr, slot->id, BTSOCK_RFCOMM, SOCKET_CONNECTION_STATE_LISTENING, + slot->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, slot->app_uid, slot->scn, 0, + 0, slot->service_name, 0, BTSOCK_ERROR_NONE, slot->data_path); } static uint32_t on_srv_rfc_connect_offload(tBTA_JV_RFCOMM_SRV_OPEN* p_open, rfc_slot_t* srv_rs) { @@ -670,7 +673,9 @@ static uint32_t on_srv_rfc_connect_offload(tBTA_JV_RFCOMM_SRV_OPEN* p_open, rfc_ btif_sock_connection_logger(accept_rs->addr, accept_rs->id, BTSOCK_RFCOMM, SOCKET_CONNECTION_STATE_CONNECTED, accept_rs->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - accept_rs->app_uid, accept_rs->scn, 0, 0, accept_rs->service_name); + accept_rs->app_uid, accept_rs->scn, 0, 0, accept_rs->service_name, 0, + BTSOCK_ERROR_NONE, accept_rs->data_path); + accept_rs->connection_start_time_ms = common::time_gettimeofday_us() / 1000; bluetooth::hal::SocketContext socket_context = { .socket_id = accept_rs->socket_id, @@ -685,10 +690,10 @@ static uint32_t on_srv_rfc_connect_offload(tBTA_JV_RFCOMM_SRV_OPEN* p_open, rfc_ }; if (!srv_rs->is_accepting) { log::warn("Server socket is not accepting. Disconnect the incoming connection."); - cleanup_rfc_slot(accept_rs); + cleanup_rfc_slot(accept_rs, BTSOCK_ERROR_OFFLOAD_SERVER_NOT_ACCEPTING); } else if (!bluetooth::shim::GetLppOffloadManager()->SocketOpened(socket_context)) { log::warn("RFCOMM socket opened failed. Disconnect the incoming connection."); - cleanup_rfc_slot(accept_rs); + cleanup_rfc_slot(accept_rs, BTSOCK_ERROR_OFFLOAD_HAL_OPEN_FAILURE); } else { log::info("RFCOMM socket opened successful. Will send connect signal in async callback."); } @@ -728,7 +733,9 @@ static uint32_t on_srv_rfc_connect(tBTA_JV_RFCOMM_SRV_OPEN* p_open, uint32_t id) btif_sock_connection_logger(accept_rs->addr, accept_rs->id, BTSOCK_RFCOMM, SOCKET_CONNECTION_STATE_CONNECTED, accept_rs->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, - accept_rs->app_uid, accept_rs->scn, 0, 0, accept_rs->service_name); + accept_rs->app_uid, accept_rs->scn, 0, 0, accept_rs->service_name, 0, + BTSOCK_ERROR_NONE, accept_rs->data_path); + accept_rs->connection_start_time_ms = common::time_gettimeofday_us() / 1000; // Start monitoring the socket. btsock_thread_add_fd(pth, srv_rs->fd, BTSOCK_RFCOMM, SOCK_THREAD_FD_EXCEPTION, srv_rs->id); @@ -755,7 +762,8 @@ static void on_cli_rfc_connect_offload(tBTA_JV_RFCOMM_OPEN* p_open, rfc_slot_t* btif_sock_connection_logger( slot->addr, slot->id, BTSOCK_RFCOMM, SOCKET_CONNECTION_STATE_CONNECTED, slot->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, slot->app_uid, slot->scn, 0, - 0, slot->service_uuid.ToString().c_str()); + 0, slot->service_uuid.ToString().c_str(), 0, BTSOCK_ERROR_NONE, slot->data_path); + slot->connection_start_time_ms = common::time_gettimeofday_us() / 1000; bluetooth::hal::SocketContext socket_context = { .socket_id = slot->socket_id, @@ -770,7 +778,7 @@ static void on_cli_rfc_connect_offload(tBTA_JV_RFCOMM_OPEN* p_open, rfc_slot_t* }; if (!bluetooth::shim::GetLppOffloadManager()->SocketOpened(socket_context)) { log::warn("RFCOMM socket opened failed. Disconnect the incoming connection."); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_OFFLOAD_HAL_OPEN_FAILURE); } else { log::info( "RFCOMM socket opened successful. Will send connect signal in " @@ -790,7 +798,7 @@ static void on_cli_rfc_connect(tBTA_JV_RFCOMM_OPEN* p_open, uint32_t id) { if (p_open->status != tBTA_JV_STATUS::SUCCESS) { log::warn("CONNECT unsuccessful, status {}. Cleaning up slot_id {}", bta_jv_status_text(p_open->status), slot->id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_CONNECTION_FAILURE); return; } @@ -811,7 +819,8 @@ static void on_cli_rfc_connect(tBTA_JV_RFCOMM_OPEN* p_open, uint32_t id) { btif_sock_connection_logger( slot->addr, slot->id, BTSOCK_RFCOMM, SOCKET_CONNECTION_STATE_CONNECTED, slot->f.server ? SOCKET_ROLE_LISTEN : SOCKET_ROLE_CONNECTION, slot->app_uid, slot->scn, 0, - 0, slot->service_uuid.ToString().c_str()); + 0, slot->service_uuid.ToString().c_str(), 0, BTSOCK_ERROR_NONE, slot->data_path); + slot->connection_start_time_ms = common::time_gettimeofday_us() / 1000; if (send_app_connect_signal(slot->fd, &slot->addr, slot->scn, 0, -1, slot->socket_id)) { slot->f.connected = true; @@ -847,7 +856,7 @@ void on_btsocket_rfc_opened_complete(uint64_t socket_id, bool success) { } if (!success) { log::error("RFCOMM opened complete failed with socket_id: {}", socket_id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_OPEN_FAILURE); return; } // If the socket was accepted from listen socket, use listen_fd. @@ -877,7 +886,7 @@ void on_btsocket_rfc_close(uint64_t socket_id) { return; } log::info("RFCOMM close request for socket_id: {}", socket_id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_NONE); } // TODO(b/380189525): Replace the randomized socket ID with static counter when we don't have @@ -904,8 +913,9 @@ static void on_rfc_close(tBTA_JV_RFCOMM_CLOSE* /* p_close */, uint32_t id) { android::bluetooth::SOCKET_CONNECTION_STATE_DISCONNECTING, 0, 0, slot->app_uid, slot->scn, slot->f.server ? android::bluetooth::SOCKET_ROLE_LISTEN - : android::bluetooth::SOCKET_ROLE_CONNECTION); - cleanup_rfc_slot(slot); + : android::bluetooth::SOCKET_ROLE_CONNECTION, + 0, android::bluetooth::SOCKET_ERROR_NONE, slot->data_path); + cleanup_rfc_slot(slot, BTSOCK_ERROR_NONE); } static void on_rfc_write_done(tBTA_JV_RFCOMM_WRITE* p, uint32_t id) { @@ -1010,7 +1020,7 @@ static void jv_dm_cback(tBTA_JV_EVT event, tBTA_JV* p_data, uint32_t id) { if (p_data->scn == 0) { log::error("Unable to allocate scn: all resources exhausted. slot found: {}", std::format_ptr(rs)); - cleanup_rfc_slot(rs); + cleanup_rfc_slot(rs, BTSOCK_ERROR_SCN_ALLOCATION_FAILURE); break; } @@ -1018,7 +1028,7 @@ static void jv_dm_cback(tBTA_JV_EVT event, tBTA_JV* p_data, uint32_t id) { // Send channel ID to java layer if (!send_app_scn(rs)) { log::warn("send_app_scn() failed, closing rs->id:{}", rs->id); - cleanup_rfc_slot(rs); + cleanup_rfc_slot(rs, BTSOCK_ERROR_SEND_SCN_FAILURE); break; } @@ -1071,7 +1081,7 @@ static void jv_dm_cback(tBTA_JV_EVT event, tBTA_JV* p_data, uint32_t id) { if (!create_server_sdp_record(slot)) { log::error("cannot start server, slot found: {}", std::format_ptr(slot)); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_ADD_SDP_FAILURE); break; } @@ -1137,7 +1147,7 @@ static void handle_discovery_comp(tBTA_JV_STATUS status, int scn, uint32_t id) { id, bta_jv_status_text(status), scn); bta_collect_rfc_metrics_after_sdp_fail(status, slot->addr, slot->app_uid, slot->security, static_cast<bool>(slot->f.server), sdp_duration_ms); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_SDP_DISCOVERY_FAILURE); return; } @@ -1159,7 +1169,7 @@ static void handle_discovery_comp(tBTA_JV_STATUS status, int scn, uint32_t id) { if (BTA_JvRfcommConnect(slot->security, scn, slot->addr, rfcomm_cback, slot->id, cfg, slot->app_uid, sdp_duration_ms) != tBTA_JV_STATUS::SUCCESS) { log::warn("BTA_JvRfcommConnect() returned BTA_JV_FAILURE for RFCOMM slot_id:{}", id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_CONNECTION_FAILURE); return; } // Establish connection if successfully found channel number to connect. @@ -1168,7 +1178,7 @@ static void handle_discovery_comp(tBTA_JV_STATUS status, int scn, uint32_t id) { if (!send_app_scn(slot)) { log::warn("send_app_scn() failed, closing slot_id {}", slot->id); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_SEND_SCN_FAILURE); return; } } @@ -1276,6 +1286,7 @@ static bool btsock_rfc_read_signaled_on_listen_socket(int fd, int /* flags */, u static void btsock_rfc_signaled_flagged(int fd, int flags, uint32_t id) { bool need_close = false; + btsock_error_code_t error_code = BTSOCK_ERROR_NONE; std::unique_lock<std::recursive_mutex> lock(slot_lock); rfc_slot_t* slot = find_rfc_slot_by_id(id); if (!slot) { @@ -1289,11 +1300,13 @@ static void btsock_rfc_signaled_flagged(int fd, int flags, uint32_t id) { // app sending data on connection socket if (!btsock_rfc_read_signaled_on_connected_socket(fd, flags, id, slot)) { need_close = true; + error_code = BTSOCK_ERROR_READ_SIGNALED_FAILURE; } } else { // app sending signal on listen socket if (!btsock_rfc_read_signaled_on_listen_socket(fd, flags, id, slot)) { need_close = true; + error_code = BTSOCK_ERROR_READ_SIGNALED_FAILURE; } } } @@ -1306,6 +1319,7 @@ static void btsock_rfc_signaled_flagged(int fd, int flags, uint32_t id) { "slot_id: {}, channel: {}", slot->id, slot->scn); need_close = true; + error_code = BTSOCK_ERROR_WRITE_SIGNALED_FAILURE; } } @@ -1317,7 +1331,7 @@ static void btsock_rfc_signaled_flagged(int fd, int flags, uint32_t id) { slot->f.doing_sdp_request) { BTA_JvCancelDiscovery(slot->id); } - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, error_code); } } } @@ -1328,6 +1342,7 @@ void btsock_rfc_signaled(int fd, int flags, uint32_t id) { return; } bool need_close = false; + btsock_error_code_t error_code = BTSOCK_ERROR_NONE; std::unique_lock<std::recursive_mutex> lock(slot_lock); rfc_slot_t* slot = find_rfc_slot_by_id(id); if (!slot) { @@ -1346,6 +1361,7 @@ void btsock_rfc_signaled(int fd, int flags, uint32_t id) { } else { log::error("socket signaled for read while disconnected, slot_id: {}, channel: {}", slot->id, slot->scn); + error_code = BTSOCK_ERROR_READ_SIGNALED_FAILURE; need_close = true; } } @@ -1357,6 +1373,7 @@ void btsock_rfc_signaled(int fd, int flags, uint32_t id) { "socket signaled for write while disconnected (or write failure), " "slot_id: {}, channel: {}", slot->id, slot->scn); + error_code = BTSOCK_ERROR_WRITE_SIGNALED_FAILURE; need_close = true; } } @@ -1369,7 +1386,7 @@ void btsock_rfc_signaled(int fd, int flags, uint32_t id) { slot->f.doing_sdp_request) { BTA_JvCancelDiscovery(slot->id); } - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, error_code); } } } @@ -1403,7 +1420,7 @@ int bta_co_rfc_data_incoming(uint32_t id, BT_HDR* p_buf) { case SENT_FAILED: osi_free(p_buf); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_SEND_TO_APP_FAILURE); break; } } else { @@ -1428,7 +1445,7 @@ int bta_co_rfc_data_outgoing_size(uint32_t id, int* size) { if (ioctl(slot->fd, FIONREAD, size) != 0) { log::error("unable to determine bytes remaining to be read on fd {}: {}", slot->fd, strerror(errno)); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_RECEIVE_DATA_FAILURE); return false; } @@ -1448,7 +1465,7 @@ int bta_co_rfc_data_outgoing(uint32_t id, uint8_t* buf, uint16_t size) { if (received != size) { log::error("error receiving RFCOMM data from app: {}", strerror(errno)); - cleanup_rfc_slot(slot); + cleanup_rfc_slot(slot, BTSOCK_ERROR_RECEIVE_DATA_FAILURE); return false; } @@ -1465,7 +1482,7 @@ bt_status_t btsock_rfc_disconnect(const RawAddress* bd_addr) { std::unique_lock<std::recursive_mutex> lock(slot_lock); for (size_t i = 0; i < ARRAY_SIZE(rfc_slots); ++i) { if (rfc_slots[i].id && rfc_slots[i].addr == *bd_addr) { - cleanup_rfc_slot(&rfc_slots[i]); + cleanup_rfc_slot(&rfc_slots[i], BTSOCK_ERROR_NONE); } } diff --git a/system/common/metrics.cc b/system/common/metrics.cc index 1ece069ab3..809b3c4d31 100644 --- a/system/common/metrics.cc +++ b/system/common/metrics.cc @@ -58,6 +58,9 @@ struct formatter<android::bluetooth::AddressTypeEnum> template <> struct formatter<android::bluetooth::DeviceInfoSrcEnum> : enum_formatter<android::bluetooth::DeviceInfoSrcEnum> {}; +template <> +struct formatter<android::bluetooth::SocketErrorEnum> + : enum_formatter<android::bluetooth::SocketErrorEnum> {}; } // namespace std namespace bluetooth { @@ -778,7 +781,10 @@ void LogSdpAttribute(const RawAddress& address, uint16_t protocol_uuid, uint16_t void LogSocketConnectionState(const RawAddress& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) { + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload) { std::string obfuscated_id; int metric_id = 0; if (!address.IsEmpty()) { @@ -790,14 +796,16 @@ void LogSocketConnectionState(const RawAddress& address, int port, int type, address.IsEmpty() ? 0 : obfuscated_id.size()); int ret = stats_write(BLUETOOTH_SOCKET_CONNECTION_STATE_CHANGED, obfuscated_id_field, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, socket_role, - metric_id, 0 /* connection_duration_ms */, 1 /* error_code */, - 0 /* is_hardware_offload */); + metric_id, static_cast<int64_t>(connection_duration_ms), error_code, + is_hardware_offload); if (ret < 0) { log::warn( "failed for {}, port {}, type {}, state {}, tx_bytes {}, rx_bytes {}, " - "uid {}, server_port {}, socket_role {}, error {}", + "uid {}, server_port {}, socket_role {}, error {}, connection_duration_ms {}, " + "socket_error_code {}, " + "is_hardware_offload {}", address, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, - socket_role, ret); + socket_role, ret, connection_duration_ms, error_code, is_hardware_offload); } } diff --git a/system/common/metrics.h b/system/common/metrics.h index 8cd41bd6db..69e7ed67ca 100644 --- a/system/common/metrics.h +++ b/system/common/metrics.h @@ -459,11 +459,17 @@ void LogSdpAttribute(const RawAddress& address, uint16_t protocol_uuid, uint16_t * by |server_port| * @param socket_role role of this socket, server or connection * @param uid socket owner's uid + * @param connection_duration_ms duration of socket connection in milliseconds + * @param error_code error code of socket failures + * @param is_hardware_offload whether this is a offload socket */ void LogSocketConnectionState(const RawAddress& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role); + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload); /** * Logs when a Bluetooth device's manufacturer information is learnt diff --git a/system/common/metrics_linux.cc b/system/common/metrics_linux.cc index 009d16878e..cfeac82dd1 100644 --- a/system/common/metrics_linux.cc +++ b/system/common/metrics_linux.cc @@ -92,7 +92,10 @@ void LogSocketConnectionState(const RawAddress& /* address */, int /* port */, i android::bluetooth::SocketConnectionstateEnum /* connection_state */, int64_t /* tx_bytes */, int64_t /* rx_bytes */, int /* uid */, int /* server_port */, - android::bluetooth::SocketRoleEnum /* socket_role */) {} + android::bluetooth::SocketRoleEnum /* socket_role */, + uint64_t /* connection_duration_ms */, + android::bluetooth::SocketErrorEnum /* error_code */, + bool /* is_hardware_offload */) {} void LogHciTimeoutEvent(uint32_t /* hci_cmd */) {} diff --git a/system/gd/os/android/metrics.cc b/system/gd/os/android/metrics.cc index 3b6d9602b0..78b12c8d96 100644 --- a/system/gd/os/android/metrics.cc +++ b/system/gd/os/android/metrics.cc @@ -66,6 +66,9 @@ struct formatter<android::bluetooth::rfcomm::SocketConnectionSecurity> : enum_formatter<android::bluetooth::rfcomm::SocketConnectionSecurity> {}; template <> struct formatter<android::bluetooth::BtaStatus> : enum_formatter<android::bluetooth::BtaStatus> {}; +template <> +struct formatter<android::bluetooth::SocketErrorEnum> + : enum_formatter<android::bluetooth::SocketErrorEnum> {}; } // namespace std namespace bluetooth { @@ -332,22 +335,28 @@ void LogMetricSdpAttribute(const Address& address, uint16_t protocol_uuid, uint1 void LogMetricSocketConnectionState(const Address& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) { + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload) { int metric_id = 0; if (!address.IsEmpty()) { metric_id = MetricIdManager::GetInstance().AllocateId(address); } + int ret = stats_write(BLUETOOTH_SOCKET_CONNECTION_STATE_CHANGED, byteField, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, socket_role, - metric_id, 0 /* connection_duration_ms */, 1 /* error_code */, - 0 /* is_hardware_offload */); + metric_id, static_cast<int64_t>(connection_duration_ms), error_code, + is_hardware_offload); + if (ret < 0) { log::warn( "Failed for {}, port {}, type {}, state {}, tx_bytes {}, rx_bytes {}, uid {}, " "server_port " - "{}, socket_role {}, error {}", + "{}, socket_role {}, error {}, connection_duration_ms {}, socket_error_code {}, " + "is_hardware_offload {}", address, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, - socket_role, ret); + socket_role, ret, connection_duration_ms, error_code, is_hardware_offload); } } diff --git a/system/gd/os/chromeos/metrics.cc b/system/gd/os/chromeos/metrics.cc index 70258d335a..b7921fe308 100644 --- a/system/gd/os/chromeos/metrics.cc +++ b/system/gd/os/chromeos/metrics.cc @@ -35,7 +35,10 @@ void LogMetricClassicPairingEvent(const Address& address, uint16_t handle, uint3 void LogMetricSocketConnectionState(const Address& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) {} + android::bluetooth::SocketRoleEnum socket_role, + uint64_t /* connection_duration_ms */, + android::bluetooth::SocketErrorEnum /* error_code */, + bool /* is_hardware_offload */) {} void LogMetricHciTimeoutEvent(uint32_t hci_cmd) {} diff --git a/system/gd/os/host/metrics.cc b/system/gd/os/host/metrics.cc index 61734e6a81..a333113238 100644 --- a/system/gd/os/host/metrics.cc +++ b/system/gd/os/host/metrics.cc @@ -32,7 +32,8 @@ void LogMetricSocketConnectionState( const Address& /* address */, int /* port */, int /* type */, android::bluetooth::SocketConnectionstateEnum /* connection_state */, int64_t /* tx_bytes */, int64_t /* rx_bytes */, int /* uid */, int /* server_port */, - android::bluetooth::SocketRoleEnum /* socket_role */) {} + android::bluetooth::SocketRoleEnum /* socket_role */, uint64_t /* connection_duration_ms */, + android::bluetooth::SocketErrorEnum /* error_code */, bool /* is_hardware_offload */) {} void LogMetricHciTimeoutEvent(uint32_t /* hci_cmd */) {} diff --git a/system/gd/os/linux/metrics.cc b/system/gd/os/linux/metrics.cc index 45fca1f4ee..7b727f38f2 100644 --- a/system/gd/os/linux/metrics.cc +++ b/system/gd/os/linux/metrics.cc @@ -30,7 +30,10 @@ void LogMetricClassicPairingEvent(const Address& address, uint16_t handle, uint3 void LogMetricSocketConnectionState(const Address& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) {} + android::bluetooth::SocketRoleEnum socket_role, + uint64_t /* connection_duration_ms */, + android::bluetooth::SocketErrorEnum /* error_code */, + bool /* is_hardware_offload */) {} void LogMetricHciTimeoutEvent(uint32_t hci_cmd) {} diff --git a/system/gd/os/metrics.h b/system/gd/os/metrics.h index 9f372b25af..aab82826e6 100644 --- a/system/gd/os/metrics.h +++ b/system/gd/os/metrics.h @@ -260,11 +260,17 @@ void LogMetricSdpAttribute(const hci::Address& address, uint16_t protocol_uuid, * by |server_port| * @param socket_role role of this socket, server or connection * @param uid socket owner's uid + * @param connection_duration_ms duration of socket connection in milliseconds + * @param error_code error code of socket failures + * @param is_hardware_offload whether this is a offload socket */ void LogMetricSocketConnectionState(const hci::Address& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role); + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload); /** * Logs when a Bluetooth device's manufacturer information is learnt diff --git a/system/include/hardware/bt_sock.h b/system/include/hardware/bt_sock.h index 0436fad9cb..340085998c 100644 --- a/system/include/hardware/bt_sock.h +++ b/system/include/hardware/bt_sock.h @@ -38,6 +38,25 @@ typedef enum { BTSOCK_L2CAP_LE = 4 } btsock_type_t; +typedef enum { + BTSOCK_ERROR_NONE = 0, + BTSOCK_ERROR_SERVER_START_FAILURE = 1, + BTSOCK_ERROR_CLIENT_INIT_FAILURE = 2, + BTSOCK_ERROR_LISTEN_FAILURE = 3, + BTSOCK_ERROR_CONNECTION_FAILURE = 4, + BTSOCK_ERROR_OPEN_FAILURE = 5, + BTSOCK_ERROR_OFFLOAD_SERVER_NOT_ACCEPTING = 6, + BTSOCK_ERROR_OFFLOAD_HAL_OPEN_FAILURE = 7, + BTSOCK_ERROR_SEND_TO_APP_FAILURE = 8, + BTSOCK_ERROR_RECEIVE_DATA_FAILURE = 9, + BTSOCK_ERROR_READ_SIGNALED_FAILURE = 10, + BTSOCK_ERROR_WRITE_SIGNALED_FAILURE = 11, + BTSOCK_ERROR_SEND_SCN_FAILURE = 12, + BTSOCK_ERROR_SCN_ALLOCATION_FAILURE = 13, + BTSOCK_ERROR_ADD_SDP_FAILURE = 14, + BTSOCK_ERROR_SDP_DISCOVERY_FAILURE = 15, +} btsock_error_code_t; + /** * Data path used for Bluetooth socket communication. * diff --git a/system/main/shim/metrics_api.cc b/system/main/shim/metrics_api.cc index f222adf82a..2250090901 100644 --- a/system/main/shim/metrics_api.cc +++ b/system/main/shim/metrics_api.cc @@ -135,10 +135,14 @@ void LogMetricSdpAttribute(const RawAddress& raw_address, uint16_t protocol_uuid void LogMetricSocketConnectionState(const RawAddress& raw_address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) { + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload) { Address address = bluetooth::ToGdAddress(raw_address); - bluetooth::os::LogMetricSocketConnectionState(address, port, type, connection_state, tx_bytes, - rx_bytes, uid, server_port, socket_role); + bluetooth::os::LogMetricSocketConnectionState( + address, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, socket_role, + connection_duration_ms, error_code, is_hardware_offload); } void LogMetricManufacturerInfo(const RawAddress& raw_address, diff --git a/system/main/shim/metrics_api.h b/system/main/shim/metrics_api.h index 3b8e369b69..143a2f754d 100644 --- a/system/main/shim/metrics_api.h +++ b/system/main/shim/metrics_api.h @@ -225,11 +225,17 @@ void LogMetricSdpAttribute(const RawAddress& address, uint16_t protocol_uuid, ui * by |server_port| * @param socket_role role of this socket, server or connection * @param uid socket owner's uid + * @param connection_duration_ms duration of socket connection in milliseconds + * @param error_code error code of socket failures + * @param is_hardware_offload whether this is a offload socket */ void LogMetricSocketConnectionState(const RawAddress& address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role); + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload); /** * Logs when a Bluetooth device's manufacturer information is learnt diff --git a/system/test/mock/mock_main_shim_metrics_api.cc b/system/test/mock/mock_main_shim_metrics_api.cc index 0a501c7e6c..e635979ed8 100644 --- a/system/test/mock/mock_main_shim_metrics_api.cc +++ b/system/test/mock/mock_main_shim_metrics_api.cc @@ -184,12 +184,13 @@ void bluetooth::shim::LogMetricSdpAttribute(const RawAddress& raw_address, uint1 void bluetooth::shim::LogMetricSocketConnectionState( const RawAddress& raw_address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, - int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) { + int64_t rx_bytes, int uid, int server_port, android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, android::bluetooth::SocketErrorEnum error_code, + bool is_hardware_offload) { inc_func_call_count(__func__); test::mock::main_shim_metrics_api::LogMetricSocketConnectionState( raw_address, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, - socket_role); + socket_role, connection_duration_ms, error_code, is_hardware_offload); } void bluetooth::shim::LogMetricManufacturerInfo( const RawAddress& raw_address, android::bluetooth::AddressTypeEnum address_type, diff --git a/system/test/mock/mock_main_shim_metrics_api.h b/system/test/mock/mock_main_shim_metrics_api.h index 887090d743..4beaab72c0 100644 --- a/system/test/mock/mock_main_shim_metrics_api.h +++ b/system/test/mock/mock_main_shim_metrics_api.h @@ -274,17 +274,23 @@ struct LogMetricSocketConnectionState { std::function<void(const RawAddress& raw_address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role)> + android::bluetooth::SocketRoleEnum socket_role, + uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, bool is_hardware_offload)> body{[](const RawAddress& /* raw_address */, int /* port */, int /* type */, android::bluetooth::SocketConnectionstateEnum /* connection_state */, int64_t /* tx_bytes */, int64_t /* rx_bytes */, int /* uid */, - int /* server_port */, android::bluetooth::SocketRoleEnum /* socket_role */) {}}; + int /* server_port */, android::bluetooth::SocketRoleEnum /* socket_role */, + uint64_t /* connection_duration_ms */, + android::bluetooth::SocketErrorEnum /* error_code */, + bool /* is_hardware_offload */) {}}; void operator()(const RawAddress& raw_address, int port, int type, android::bluetooth::SocketConnectionstateEnum connection_state, int64_t tx_bytes, int64_t rx_bytes, int uid, int server_port, - android::bluetooth::SocketRoleEnum socket_role) { + android::bluetooth::SocketRoleEnum socket_role, uint64_t connection_duration_ms, + android::bluetooth::SocketErrorEnum error_code, bool is_hardware_offload) { body(raw_address, port, type, connection_state, tx_bytes, rx_bytes, uid, server_port, - socket_role); + socket_role, connection_duration_ms, error_code, is_hardware_offload); } }; extern struct LogMetricSocketConnectionState LogMetricSocketConnectionState; |