HCI: Get debug info from the firmware on timeout (80b755fa) · Commits · e / os / android_packages_modules_Bluetooth

system/hci/src/hci_layer.cc

+54 −4

Original line number	Diff line number	Diff line
		@@ -53,6 +53,11 @@
		extern void hci_initialize();
		extern void hci_transmit(BT_HDR* packet);
		extern void hci_close();
		extern int hci_open_firmware_log_file();
		extern void hci_close_firmware_log_file(int fd);
		extern void hci_log_firmware_debug_packet(int fd, BT_HDR* packet);

		static int hci_firmware_log_fd = INVALID_FD;

		typedef struct {
		uint16_t opcode;
		@@ -73,6 +78,7 @@ static const int BT_HCI_RT_PRIORITY = 1;

		// Abort if there is no response to an HCI command.
		static const uint32_t COMMAND_PENDING_TIMEOUT_MS = 2000;
		static const uint32_t COMMAND_TIMEOUT_RESTART_US = 500000;

		// Our interface
		static bool interface_created;
		@@ -452,16 +458,51 @@ static void command_timed_out(UNUSED_ATTR void* context) {
		std::chrono::duration_cast<std::chrono::milliseconds>(
		std::chrono::steady_clock::now() - wait_entry->timestamp)
		.count();
		// We shouldn't try to recover the stack from this command timeout.
		// If it's caused by a software bug, fix it. If it's a hardware bug, fix it.
		LOG_ERROR(LOG_TAG, "%s: Waited %d ms for a response to opcode: 0x%x",
		__func__, wait_time_ms, wait_entry->opcode);

		// Dump the length field and the first byte of the payload, if present.
		uint8_t* command = wait_entry->command->data + wait_entry->command->offset;
		if (wait_entry->command->len > 3)
		LOG_ERROR(LOG_TAG, "%s: Size %d Hex %02x %02x %02x %02x", __func__,
		wait_entry->command->len, command[0], command[1], command[2],
		command[3]);
		else
		LOG_ERROR(LOG_TAG, "%s: Size %d Hex %02x %02x %02x", __func__,
		wait_entry->command->len, command[0], command[1], command[2]);

		LOG_EVENT_INT(BT_HCI_TIMEOUT_TAG_NUM, wait_entry->opcode);
		lock.unlock();
		}

		LOG_ERROR(LOG_TAG, "%s restarting the bluetooth process.", __func__);
		usleep(10000);
		LOG_ERROR(LOG_TAG, "%s: requesting a firmware dump.", __func__);

		/* Allocate a buffer to hold the HCI command. */
		BT_HDR* bt_hdr =
		static_cast<BT_HDR*>(osi_malloc(sizeof(BT_HDR) + HCIC_PREAMBLE_SIZE));

		bt_hdr->len = HCIC_PREAMBLE_SIZE;
		bt_hdr->event = MSG_STACK_TO_HC_HCI_CMD;
		bt_hdr->offset = 0;

		uint8_t* hci_packet = reinterpret_cast<uint8_t*>(bt_hdr + 1);

		UINT16_TO_STREAM(hci_packet,
		HCI_GRP_VENDOR_SPECIFIC \| HCI_CONTROLLER_DEBUG_INFO_OCF);
		UINT8_TO_STREAM(hci_packet, 0); // No parameters

		hci_firmware_log_fd = hci_open_firmware_log_file();

		transmit_fragment(bt_hdr, true);

		osi_free(bt_hdr);

		LOG_ERROR(LOG_TAG, "%s restarting the Bluetooth process.", __func__);
		usleep(COMMAND_TIMEOUT_RESTART_US);
		hci_close_firmware_log_file(hci_firmware_log_fd);

		// We shouldn't try to recover the stack from this command timeout.
		// If it's caused by a software bug, fix it. If it's a hardware bug, fix it.
		abort();
		}

		@@ -544,6 +585,15 @@ static bool filter_incoming_event(BT_HDR* packet) {
		}

		goto intercepted;
		} else if (event_code == HCI_VSE_SUBCODE_DEBUG_INFO_SUB_EVT) {
		if (hci_firmware_log_fd == INVALID_FD)
		hci_firmware_log_fd = hci_open_firmware_log_file();

		if (hci_firmware_log_fd != INVALID_FD)
		hci_log_firmware_debug_packet(hci_firmware_log_fd, packet);

		buffer_allocator->free(packet);
		return true;
		}

		return false;

system/hci/src/hci_layer_android.cc

+31 −0

Original line number	Diff line number	Diff line
		@@ -24,12 +24,17 @@
		#include <base/logging.h>
		#include "buffer_allocator.h"
		#include "osi/include/log.h"
		#include "sys/stat.h"
		#include "sys/types.h"

		#include <android/hardware/bluetooth/1.0/IBluetoothHci.h>
		#include <android/hardware/bluetooth/1.0/IBluetoothHciCallbacks.h>
		#include <android/hardware/bluetooth/1.0/types.h>
		#include <hwbinder/ProcessState.h>

		#define LOG_PATH "/data/misc/bluetooth/logs/firmware_events.log"
		#define LAST_LOG_PATH "/data/misc/bluetooth/logs/firmware_events.log.last"

		using android::hardware::bluetooth::V1_0::IBluetoothHci;
		using android::hardware::bluetooth::V1_0::IBluetoothHciCallbacks;
		using android::hardware::bluetooth::V1_0::HciPacket;
		@@ -135,3 +140,29 @@ void hci_transmit(BT_HDR* packet) {
		break;
		}
		}

		int hci_open_firmware_log_file() {
		if (rename(LOG_PATH, LAST_LOG_PATH) == -1 && errno != ENOENT) {
		LOG_ERROR(LOG_TAG, "%s unable to rename '%s' to '%s': %s", __func__,
		LOG_PATH, LAST_LOG_PATH, strerror(errno));
		}

		mode_t prevmask = umask(0);
		int logfile_fd = open(LOG_PATH, 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(LOG_TAG, "%s unable to open '%s': %s", __func__, LOG_PATH,
		strerror(errno));
		}

		return logfile_fd;
		}

		void hci_close_firmware_log_file(int fd) {
		if (fd != INVALID_FD) close(fd);
		}

		void hci_log_firmware_debug_packet(int fd, BT_HDR* packet) {
		TEMP_FAILURE_RETRY(write(fd, packet->data, packet->len));
		}

system/hci/src/hci_layer_linux.cc

+6 −0

Original line number	Diff line number	Diff line
		@@ -392,3 +392,9 @@ static int rfkill(int block) {
		close(fd);
		return 0;
		}

		int hci_open_firmware_log_file() { return INVALID_FD; }

		void hci_close_firmware_log_file(int fd) {}

		void hci_log_firmware_debug_packet(int fd, BT_HDR* packet) {}

system/stack/include/hcidefs.h

+3 −0

Original line number	Diff line number	Diff line
		@@ -423,6 +423,9 @@
		/* tracking sub event */
		#define HCI_VSE_SUBCODE_BLE_TRACKING_SUB_EVT 0x56 /* Tracking event */

		/* debug info sub event */
		#define HCI_VSE_SUBCODE_DEBUG_INFO_SUB_EVT 0x57

		/* LE supported states definition */
		#define HCI_LE_ADV_STATE 0x00000001
		#define HCI_LE_SCAN_STATE 0x00000002