Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit bd662a8d authored by Jack He's avatar Jack He
Browse files

GD-HCI: Implement snoop rotation and options parsing 

* Implement btsnoop log rotation that creates a new log
  after logging 0xFFFF (65535) packets
* Implement btsnoop log mode parsing from system properties

Bug: 163733538
Test: atest bluetooth_test_gd
Tag: #gd-refactor
Change-Id: I577339bc5a6cd9f814a00916cb85099bda7b06da
parent a2bdc02e

system/gd/Android.bp

+1 −0
Original line number Diff line number Diff line
@@ -285,6 +285,7 @@ cc_test { 
        ":BluetoothCommonTestSources",

        ":BluetoothCryptoToolboxTestSources",

        ":BluetoothDumpsysTestSources",

        ":BluetoothHalTestSources",

        ":BluetoothHciTestSources",

        ":BluetoothL2capTestSources",

        ":BluetoothNeighborTestSources",

system/gd/hal/Android.bp

+7 −0
Original line number Diff line number Diff line
@@ -5,6 +5,13 @@ filegroup { 
    ],

}



filegroup {

    name: "BluetoothHalTestSources",

    srcs: [

        "snoop_logger_test.cc",

    ],

}



filegroup {

    name: "BluetoothHalSources_hci_rootcanal",

    srcs: [

system/gd/hal/hci_hal_android_hidl.cc

+6 −9
Original line number Diff line number Diff line
@@ -74,7 +74,7 @@ class InternalHciCallbacks : public IBluetoothHciCallbacks { 


  Return<void> hciEventReceived(const hidl_vec<uint8_t>& event) {

    std::vector<uint8_t> received_hci_packet(event.begin(), event.end());

    btsnoop_logger_->capture(received_hci_packet, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::EVT);

    btsnoop_logger_->Capture(received_hci_packet, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::EVT);

    if (callback_ != nullptr) {

      callback_->hciEventReceived(std::move(received_hci_packet));

    }
@@ -83,7 +83,7 @@ class InternalHciCallbacks : public IBluetoothHciCallbacks { 


  Return<void> aclDataReceived(const hidl_vec<uint8_t>& data) {

    std::vector<uint8_t> received_hci_packet(data.begin(), data.end());

    btsnoop_logger_->capture(received_hci_packet, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::ACL);

    btsnoop_logger_->Capture(received_hci_packet, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::ACL);

    if (callback_ != nullptr) {

      callback_->aclDataReceived(std::move(received_hci_packet));

    }
@@ -92,7 +92,7 @@ class InternalHciCallbacks : public IBluetoothHciCallbacks { 


  Return<void> scoDataReceived(const hidl_vec<uint8_t>& data) {

    std::vector<uint8_t> received_hci_packet(data.begin(), data.end());

    btsnoop_logger_->capture(received_hci_packet, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::SCO);

    btsnoop_logger_->Capture(received_hci_packet, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::SCO);

    if (callback_ != nullptr) {

      callback_->scoDataReceived(std::move(received_hci_packet));

    }
@@ -107,9 +107,6 @@ class InternalHciCallbacks : public IBluetoothHciCallbacks { 


}  // namespace



const std::string SnoopLogger::DefaultFilePath = "/data/misc/bluetooth/logs/btsnoop_hci.log";

const bool SnoopLogger::AlwaysFlush = false;



class HciHalHidl : public HciHal {

 public:

  void registerIncomingPacketCallback(HciHalCallbacks* callback) override {
@@ -121,17 +118,17 @@ class HciHalHidl : public HciHal { 
  }



  void sendHciCommand(HciPacket command) override {

    btsnoop_logger_->capture(command, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::CMD);

    btsnoop_logger_->Capture(command, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::CMD);

    bt_hci_->sendHciCommand(command);

  }



  void sendAclData(HciPacket packet) override {

    btsnoop_logger_->capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::ACL);

    btsnoop_logger_->Capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::ACL);

    bt_hci_->sendAclData(packet);

  }



  void sendScoData(HciPacket packet) override {

    btsnoop_logger_->capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::SCO);

    btsnoop_logger_->Capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::SCO);

    bt_hci_->sendScoData(packet);

  }

system/gd/hal/hci_hal_host_rootcanal.cc

+6 −9
Original line number Diff line number Diff line
@@ -88,9 +88,6 @@ int ConnectToRootCanal(const std::string& server, int port) { 
namespace bluetooth {

namespace hal {



const std::string SnoopLogger::DefaultFilePath = "/tmp/btsnoop_hci.log";

const bool SnoopLogger::AlwaysFlush = true;



class HciHalHostRootcanal : public HciHal {

 public:

  void registerIncomingPacketCallback(HciHalCallbacks* callback) override {
@@ -118,7 +115,7 @@ class HciHalHostRootcanal : public HciHal { 
    std::lock_guard<std::mutex> lock(api_mutex_);

    ASSERT(sock_fd_ != INVALID_FD);

    std::vector<uint8_t> packet = std::move(command);

    btsnoop_logger_->capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::CMD);

    btsnoop_logger_->Capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::CMD);

    packet.insert(packet.cbegin(), kH4Command);

    write_to_rootcanal_fd(packet);

  }
@@ -127,7 +124,7 @@ class HciHalHostRootcanal : public HciHal { 
    std::lock_guard<std::mutex> lock(api_mutex_);

    ASSERT(sock_fd_ != INVALID_FD);

    std::vector<uint8_t> packet = std::move(data);

    btsnoop_logger_->capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::ACL);

    btsnoop_logger_->Capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::ACL);

    packet.insert(packet.cbegin(), kH4Acl);

    write_to_rootcanal_fd(packet);

  }
@@ -136,7 +133,7 @@ class HciHalHostRootcanal : public HciHal { 
    std::lock_guard<std::mutex> lock(api_mutex_);

    ASSERT(sock_fd_ != INVALID_FD);

    std::vector<uint8_t> packet = std::move(data);

    btsnoop_logger_->capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::SCO);

    btsnoop_logger_->Capture(packet, SnoopLogger::Direction::OUTGOING, SnoopLogger::PacketType::SCO);

    packet.insert(packet.cbegin(), kH4Sco);

    write_to_rootcanal_fd(packet);

  }
@@ -257,7 +254,7 @@ class HciHalHostRootcanal : public HciHal { 


      HciPacket receivedHciPacket;

      receivedHciPacket.assign(buf + kH4HeaderSize, buf + kH4HeaderSize + kHciEvtHeaderSize + payload_size);

      btsnoop_logger_->capture(receivedHciPacket, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::EVT);

      btsnoop_logger_->Capture(receivedHciPacket, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::EVT);

      {

        std::lock_guard<std::mutex> incoming_packet_callback_lock(incoming_packet_callback_mutex_);

        if (incoming_packet_callback_ == nullptr) {
@@ -286,7 +283,7 @@ class HciHalHostRootcanal : public HciHal { 


      HciPacket receivedHciPacket;

      receivedHciPacket.assign(buf + kH4HeaderSize, buf + kH4HeaderSize + kHciAclHeaderSize + payload_size);

      btsnoop_logger_->capture(receivedHciPacket, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::ACL);

      btsnoop_logger_->Capture(receivedHciPacket, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::ACL);

      {

        std::lock_guard<std::mutex> incoming_packet_callback_lock(incoming_packet_callback_mutex_);

        if (incoming_packet_callback_ == nullptr) {
@@ -310,7 +307,7 @@ class HciHalHostRootcanal : public HciHal { 


      HciPacket receivedHciPacket;

      receivedHciPacket.assign(buf + kH4HeaderSize, buf + kH4HeaderSize + kHciScoHeaderSize + payload_size);

      btsnoop_logger_->capture(receivedHciPacket, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::SCO);

      btsnoop_logger_->Capture(receivedHciPacket, SnoopLogger::Direction::INCOMING, SnoopLogger::PacketType::SCO);

      {

        std::lock_guard<std::mutex> incoming_packet_callback_lock(incoming_packet_callback_mutex_);

        if (incoming_packet_callback_ == nullptr) {

system/gd/hal/snoop_logger.cc

+204 −48
Original line number Diff line number Diff line
@@ -17,33 +17,24 @@ 
#include "hal/snoop_logger.h"



#include <arpa/inet.h>

#include <netinet/in.h>

#include <sys/stat.h>



#include <bitset>

#include <chrono>



#include "common/strings.h"

#include "os/files.h"

#include "os/log.h"

#include "os/parameter_provider.h"

#include "os/system_properties.h"



namespace bluetooth {

namespace hal {



namespace {

typedef struct {

  uint32_t length_original;

  uint32_t length_captured;

  uint32_t flags;

  uint32_t dropped_packets;

  uint64_t timestamp;

  uint8_t type;

} __attribute__((__packed__)) btsnoop_packet_header_t;



typedef struct {

  uint8_t identification_pattern[8];

  uint32_t version_number;

  uint32_t datalink_type;

} __attribute__((__packed__)) btsnoop_file_header_t;



constexpr uint64_t BTSNOOP_EPOCH_DELTA = 0x00dcddb30f2f8000ULL;



// Epoch in microseconds since 01/01/0000.

constexpr uint64_t kBtSnoopEpochDelta = 0x00dcddb30f2f8000ULL;



constexpr uint32_t kBytesToTest = 0x12345678;

constexpr uint8_t kFirstByte = (const uint8_t&)kBytesToTest;
@@ -62,36 +53,133 @@ uint64_t htonll(uint64_t ll) { 
  }

}



constexpr btsnoop_file_header_t BTSNOOP_FILE_HEADER = {

constexpr SnoopLogger::FileHeaderType kBtSnoopFileHeader = {

    .identification_pattern = {'b', 't', 's', 'n', 'o', 'o', 'p', 0x00},

    .version_number = BTSNOOP_VERSION_NUMBER,

    .datalink_type = BTSNOOP_DATALINK_TYPE};



// The number of packets per btsnoop file before we rotate to the next file. As of right now there

// are two snoop files that are rotated through. The size can be dynamically configured by setting

// the relevant system property

constexpr size_t kDefaultBtSnoopMaxPacketsPerFile = 0xffff;



std::string get_btsnoop_log_path(std::string btsnoop_path, bool filtered) {

  if (filtered) {

    return btsnoop_path.append(".filtered");

  }

  return btsnoop_path;

}



std::string get_btsnoop_last_log_path(std::string btsnoop_path) {

  return btsnoop_path.append(".last");

}



void delete_btsnoop_files(const std::string& log_path) {

  LOG_INFO("Deleting snoop logs if they exist");

  if (os::FileExists(log_path)) {

    if (!os::RemoveFile(log_path)) {

      LOG_ERROR("Failed to remove main snoop log faile at \"%s\"", log_path.c_str());

    }

  } else {

    LOG_INFO("Main snoop log file does not exist at \"%s\"", log_path.c_str());

  }

  auto last_log_path = get_btsnoop_last_log_path(log_path);

  if (os::FileExists(last_log_path)) {

    if (!os::RemoveFile(last_log_path)) {

      LOG_ERROR("Failed to remove last snoop log faile at \"%s\"", log_path.c_str());

    }

  } else {

    LOG_INFO("Last snoop log file does not exist at \"%s\"", log_path.c_str());

  }

}



}  // namespace



SnoopLogger::SnoopLogger() {

  bool file_exists;

  {

    std::ifstream btsnoop_istream(file_path);

    file_exists = btsnoop_istream.is_open();

std::string SnoopLogger::user_file_path_ = "";

const std::string SnoopLogger::kBtSnoopLogModeDisabled = "disabled";

const std::string SnoopLogger::kBtSnoopLogModeFiltered = "filtered";

const std::string SnoopLogger::kBtSnoopLogModeFull = "full";



const std::string SnoopLogger::kBtSnoopMaxPacketsPerFileProperty = "persist.bluetooth.btsnoopsize";

const std::string SnoopLogger::kIsDebuggableProperty = "ro.debuggable";

const std::string SnoopLogger::kBtSnoopLogModeProperty = "persist.bluetooth.btsnooplogmode";

const std::string SnoopLogger::kBtSnoopDefaultLogModeProperty = "persist.bluetooth.btsnoopdefaultmode";



SnoopLogger::SnoopLogger(std::string log_path, size_t max_packets_per_file, const std::string& btsnoop_mode)

    : file_path_(std::move(log_path)), max_packets_per_file_(max_packets_per_file) {

  if (false && btsnoop_mode == kBtSnoopLogModeFiltered) {

    // TODO(b/163733538): implement filtered snoop log in GD, currently filtered == disabled

    LOG_INFO("Filtered Snoop Logs enabled");

    is_enabled_ = true;

    is_filtered_ = true;

    // delete unfiltered logs

    delete_btsnoop_files(get_btsnoop_log_path(file_path_, false));

  } else if (btsnoop_mode == kBtSnoopLogModeFull) {

    LOG_INFO("Snoop Logs fully enabled");

    is_enabled_ = true;

    is_filtered_ = false;

    // delete filtered logs

    delete_btsnoop_files(get_btsnoop_log_path(file_path_, true));

  } else {

    LOG_INFO("Snoop Logs disabled");

    is_enabled_ = false;

    is_filtered_ = false;

    // delete both filtered and unfiltered logs

    delete_btsnoop_files(get_btsnoop_log_path(file_path_, true));

    delete_btsnoop_files(get_btsnoop_log_path(file_path_, false));

  }

  // Add ".filtered" extension if necessary

  file_path_ = get_btsnoop_log_path(file_path_, is_filtered_);

}



void SnoopLogger::CloseCurrentSnoopLogFile() {

  std::lock_guard<std::recursive_mutex> lock(file_mutex_);

  if (btsnoop_ostream_.is_open()) {

    btsnoop_ostream_.flush();

    btsnoop_ostream_.close();

  }

  packet_counter_ = 0;

}



void SnoopLogger::OpenNextSnoopLogFile() {

  std::lock_guard<std::recursive_mutex> lock(file_mutex_);

  CloseCurrentSnoopLogFile();



  auto last_file_path = get_btsnoop_last_log_path(file_path_);



  if (os::FileExists(file_path_)) {

    if (!os::RenameFile(file_path_, last_file_path)) {

      LOG_ERROR(

          "Unabled to rename existing snoop log from \"%s\" to \"%s\"", file_path_.c_str(), last_file_path.c_str());

    }

  btsnoop_ostream_.open(file_path, std::ios::binary | std::ios::app | std::ios::out);

  if (!file_exists) {

    LOG_INFO("Creating new BTSNOOP");

    btsnoop_ostream_.write(reinterpret_cast<const char*>(&BTSNOOP_FILE_HEADER), sizeof(btsnoop_file_header_t));

  } else {

    LOG_INFO("Appending to old BTSNOOP");

    LOG_INFO("Previous log file \"%s\" does not exist, skip renaming", file_path_.c_str());

  }



  mode_t prevmask = umask(0);

  // do not use std::ios::app as we want override the existing file

  btsnoop_ostream_.open(file_path_, std::ios::binary | std::ios::out);

  if (!btsnoop_ostream_.good()) {

    LOG_ALWAYS_FATAL("Unable to open snoop log at \"%s\", error: \"%s\"", file_path_.c_str(), strerror(errno));

  }

  umask(prevmask);

  if (!btsnoop_ostream_.write(reinterpret_cast<const char*>(&kBtSnoopFileHeader), sizeof(FileHeaderType))) {

    LOG_ALWAYS_FATAL("Unable to write file header to \"%s\", error: \"%s\"", file_path_.c_str(), strerror(errno));

  }

}



void SnoopLogger::SetFilePath(const std::string& filename) {

  file_path = filename;

void SnoopLogger::SetFilePath(std::string filename) {

  user_file_path_ = std::move(filename);

}



void SnoopLogger::capture(const HciPacket& packet, Direction direction, PacketType type) {

void SnoopLogger::Capture(const HciPacket& packet, Direction direction, PacketType type) {

  if (!is_enabled_) {

    // btsnoop disabled

    return;

  }

  uint64_t timestamp_us =

      std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch())

          .count();

  std::lock_guard<std::mutex> lock(file_mutex_);

  std::bitset<32> flags = 0;

  switch (type) {

    case PacketType::CMD:
@@ -99,9 +187,6 @@ void SnoopLogger::capture(const HciPacket& packet, Direction direction, PacketTy 
      flags.set(1, true);

      break;

    case PacketType::ACL:

      flags.set(0, direction == Direction::INCOMING);

      flags.set(1, false);

      break;

    case PacketType::SCO:

      flags.set(0, direction == Direction::INCOMING);

      flags.set(1, false);
@@ -112,28 +197,99 @@ void SnoopLogger::capture(const HciPacket& packet, Direction direction, PacketTy 
      break;

  }

  uint32_t length = packet.size() + /* type byte */ 1;

  btsnoop_packet_header_t header = {.length_original = htonl(length),

  PacketHeaderType header = {.length_original = htonl(length),

                             .length_captured = htonl(length),

                             .flags = htonl(static_cast<uint32_t>(flags.to_ulong())),

                             .dropped_packets = 0,

                                    .timestamp = htonll(timestamp_us + BTSNOOP_EPOCH_DELTA),

                             .timestamp = htonll(timestamp_us + kBtSnoopEpochDelta),

                             .type = static_cast<uint8_t>(type)};

  btsnoop_ostream_.write(reinterpret_cast<const char*>(&header), sizeof(btsnoop_packet_header_t));

  btsnoop_ostream_.write(reinterpret_cast<const char*>(packet.data()), packet.size());

  if (AlwaysFlush) btsnoop_ostream_.flush();

  {

    std::lock_guard<std::recursive_mutex> lock(file_mutex_);

    packet_counter_++;

    if (packet_counter_ > max_packets_per_file_) {

      OpenNextSnoopLogFile();

    }

    if (!btsnoop_ostream_.write(reinterpret_cast<const char*>(&header), sizeof(PacketHeaderType))) {

      LOG_ERROR("Failed to write packet header, error: \"%s\"", strerror(errno));

    }

    if (!btsnoop_ostream_.write(reinterpret_cast<const char*>(packet.data()), packet.size())) {

      LOG_ERROR("Failed to write packet payload, error: \"%s\"", strerror(errno));

    }

    if (os::ParameterProvider::SnoopLogAlwaysFlush()) {

      if (!btsnoop_ostream_.flush()) {

        LOG_ERROR("Failed to flush, error: \"%s\"", strerror(errno));

      }

    }

  }

}



void SnoopLogger::ListDependencies(ModuleList* list) {

  // We have no dependencies

}



void SnoopLogger::Start() {}

void SnoopLogger::Start() {

  std::lock_guard<std::recursive_mutex> lock(file_mutex_);

  if (is_enabled_) {

    OpenNextSnoopLogFile();

  }

}



void SnoopLogger::Stop() {}

void SnoopLogger::Stop() {

  std::lock_guard<std::recursive_mutex> lock(file_mutex_);

  CloseCurrentSnoopLogFile();

}



std::string SnoopLogger::file_path = SnoopLogger::DefaultFilePath;

size_t SnoopLogger::GetMaxPacketsPerFile() {

  // Allow override max packet per file via system property

  auto max_packets_per_file = kDefaultBtSnoopMaxPacketsPerFile;

  {

    auto max_packets_per_file_prop = os::GetSystemProperty(kBtSnoopMaxPacketsPerFileProperty);

    if (max_packets_per_file_prop) {

      auto max_packets_per_file_number = common::Uint64FromString(max_packets_per_file_prop.value());

      if (max_packets_per_file_number) {

        max_packets_per_file = max_packets_per_file_number.value();

      }

    }

  }

  return max_packets_per_file;

}



std::string SnoopLogger::GetBtSnoopMode() {

  // Default mode is DISABLED on user build.

  // In userdebug/eng build, it can also be overwritten by modifying the global setting

  std::string default_mode = kBtSnoopLogModeDisabled;

  {

    auto is_debuggable = os::GetSystemProperty(kIsDebuggableProperty);

    if (is_debuggable.has_value() && common::StringTrim(is_debuggable.value()) == "1") {

      auto default_mode_property = os::GetSystemProperty(kBtSnoopDefaultLogModeProperty);

      if (default_mode_property) {

        default_mode = std::move(default_mode_property.value());

      }

    }

  }



  // Get the actual mode if exist

  std::string btsnoop_mode = default_mode;

  {

    auto btsnoop_mode_prop = os::GetSystemProperty(kBtSnoopLogModeProperty);

    if (btsnoop_mode_prop) {

      btsnoop_mode = std::move(btsnoop_mode_prop.value());

    }

  }

  return btsnoop_mode;

}



std::string SnoopLogger::GetLogPath() {

  // Allow user override through SetFilePath() API

  auto log_path = os::ParameterProvider::SnoopLogFilePath();

  if (!user_file_path_.empty()) {

    log_path = user_file_path_;

  }

  return log_path;

}



const ModuleFactory SnoopLogger::Factory = ModuleFactory([]() { return new SnoopLogger(); });

const ModuleFactory SnoopLogger::Factory =

    ModuleFactory([]() { return new SnoopLogger(GetLogPath(), GetMaxPacketsPerFile(), GetBtSnoopMode()); });



}  // namespace hal

}  // namespace bluetooth