system/gd/hal/snoop_logger.cc

/*
 * 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 "hal/snoop_logger.h"

#include <arpa/inet.h>
#include <sys/stat.h>

#include <algorithm>
#include <bitset>
#include <chrono>
#include <sstream>

#include "common/circular_buffer.h"
#include "common/init_flags.h"
#include "common/strings.h"
#include "os/fake_timer/fake_timerfd.h"
#include "os/files.h"
#include "os/log.h"
#include "os/parameter_provider.h"
#include "os/system_properties.h"

namespace bluetooth {
#ifdef USE_FAKE_TIMERS
using os::fake_timer::fake_timerfd_get_clock;
#endif
namespace hal {

namespace {

// 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;
constexpr bool isLittleEndian = kFirstByte == 0x78;
constexpr bool isBigEndian = kFirstByte == 0x12;
static_assert(isLittleEndian || isBigEndian && isLittleEndian != isBigEndian);

constexpr uint32_t BTSNOOP_VERSION_NUMBER = isLittleEndian ? 0x01000000 : 1;
constexpr uint32_t BTSNOOP_DATALINK_TYPE =
    isLittleEndian ? 0xea030000 : 0x03ea;  // Datalink Type code for HCI UART (H4) is 1002
uint64_t htonll(uint64_t ll) {
  if constexpr (isLittleEndian) {
    return static_cast<uint64_t>(htonl(ll & 0xffffffff)) << 32 | htonl(ll >> 32);
  } else {
    return ll;
  }
}

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;

// We restrict the maximum packet size to 150 bytes
constexpr size_t kDefaultBtSnoozMaxBytesPerPacket = 150;
constexpr size_t kDefaultBtSnoozMaxPayloadBytesPerPacket =
    kDefaultBtSnoozMaxBytesPerPacket - sizeof(SnoopLogger::PacketHeaderType);

using namespace std::chrono_literals;
constexpr std::chrono::hours kBtSnoozLogLifeTime = 12h;
constexpr std::chrono::hours kBtSnoozLogDeleteRepeatingAlarmInterval = 1h;

std::string get_btsnoop_log_path(std::string log_dir, bool filtered) {
  if (filtered) {
    log_dir.append(".filtered");
  }
  return log_dir;
}

std::string get_last_log_path(std::string log_file_path) {
  return log_file_path.append(".last");
}

void delete_btsnoop_files(const std::string& log_path) {
  LOG_INFO("Deleting logs if they exist");
  if (os::FileExists(log_path)) {
    if (!os::RemoveFile(log_path)) {
      LOG_ERROR("Failed to remove main log file at \"%s\"", log_path.c_str());
    }
  } else {
    LOG_INFO("Main log file does not exist at \"%s\"", log_path.c_str());
  }
  auto last_log_path = get_last_log_path(log_path);
  if (os::FileExists(last_log_path)) {
    if (!os::RemoveFile(last_log_path)) {
      LOG_ERROR("Failed to remove last log file at \"%s\"", log_path.c_str());
    }
  } else {
    LOG_INFO("Last log file does not exist at \"%s\"", log_path.c_str());
  }
}

void delete_old_btsnooz_files(const std::string& log_path, const std::chrono::milliseconds log_life_time) {
  auto opt_created_ts = os::FileCreatedTime(log_path);
  if (!opt_created_ts) return;
#ifdef USE_FAKE_TIMERS
  auto diff = fake_timerfd_get_clock() - file_creation_time;
  uint64_t log_lifetime = log_life_time.count();
  if (diff >= log_lifetime) {
#else
  using namespace std::chrono;
  auto created_tp = opt_created_ts.value();
  auto current_tp = std::chrono::system_clock::now();

  auto diff = duration_cast<milliseconds>(current_tp - created_tp);
  if (diff >= log_life_time) {
#endif
    delete_btsnoop_files(log_path);
  }
}

size_t get_btsnooz_packet_length_to_write(
    const HciPacket& packet, SnoopLogger::PacketType type, bool qualcomm_debug_log_enabled) {
  static const size_t kAclHeaderSize = 4;
  static const size_t kL2capHeaderSize = 4;
  static const size_t kL2capCidOffset = (kAclHeaderSize + 2);
  static const uint16_t kL2capSignalingCid = 0x0001;

  static const size_t kHciAclHandleOffset = 0;
  static const uint16_t kQualcommDebugLogHandle = 0xedc;

  // Maximum amount of ACL data to log.
  // Enough for an RFCOMM frame up to the frame check;
  // not enough for a HID report or audio data.
  static const size_t kMaxBtsnoozAclSize = 14;

  // Calculate packet length to be included
  size_t included_length = 0;
  switch (type) {
    case SnoopLogger::PacketType::CMD:
    case SnoopLogger::PacketType::EVT:
      included_length = packet.size();
      break;

    case SnoopLogger::PacketType::ACL: {
      // Log ACL and L2CAP header by default
      size_t len_hci_acl = kAclHeaderSize + kL2capHeaderSize;
      // Check if we have enough data for an L2CAP header
      if (packet.size() > len_hci_acl) {
        uint16_t l2cap_cid =
            static_cast<uint16_t>(packet[kL2capCidOffset]) |
            static_cast<uint16_t>((static_cast<uint16_t>(packet[kL2capCidOffset + 1]) << static_cast<uint16_t>(8)));
        uint16_t hci_acl_packet_handle =
            static_cast<uint16_t>(packet[kHciAclHandleOffset]) |
            static_cast<uint16_t>((static_cast<uint16_t>(packet[kHciAclHandleOffset + 1]) << static_cast<uint16_t>(8)));
        hci_acl_packet_handle &= 0x0fff;

        if (l2cap_cid == kL2capSignalingCid) {
          // For the signaling CID, take the full packet.
          // That way, the PSM setup is captured, allowing decoding of PSMs down
          // the road.
          return packet.size();
        } else if (qualcomm_debug_log_enabled && hci_acl_packet_handle == kQualcommDebugLogHandle) {
          return packet.size();
        } else {
          // Otherwise, return as much as we reasonably can
          len_hci_acl = kMaxBtsnoozAclSize;
        }
      }
      included_length = std::min(len_hci_acl, packet.size());
      break;
    }

    case SnoopLogger::PacketType::ISO:
    case SnoopLogger::PacketType::SCO:
    default:
      // We are not logging SCO and ISO packets in snooz log as they may contain voice data
      break;
  }
  return std::min(included_length, kDefaultBtSnoozMaxPayloadBytesPerPacket);
}

}  // namespace

const std::string SnoopLogger::kBtSnoopLogModeDisabled = "disabled";
const std::string SnoopLogger::kBtSnoopLogModeTruncated = "truncated";
const std::string SnoopLogger::kBtSnoopLogModeFiltered = "filtered";
const std::string SnoopLogger::kBtSnoopLogModeFull = "full";
const std::string SnoopLogger::kSoCManufacturerQualcomm = "Qualcomm";

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";
const std::string SnoopLogger::kSoCManufacturerProperty = "ro.soc.manufacturer";

// The max ACL packet size (in bytes) in truncated logging mode. All information
// past this point is truncated from a packet.
static constexpr uint32_t kMaxTruncatedAclPacketSize = 100;

SnoopLogger::SnoopLogger(
    std::string snoop_log_path,
    std::string snooz_log_path,
    size_t max_packets_per_file,
    size_t max_packets_per_buffer,
    const std::string& btsnoop_mode,
    bool qualcomm_debug_log_enabled,
    const std::chrono::milliseconds snooz_log_life_time,
    const std::chrono::milliseconds snooz_log_delete_alarm_interval)
    : snoop_log_path_(std::move(snoop_log_path)),
      snooz_log_path_(std::move(snooz_log_path)),
      max_packets_per_file_(max_packets_per_file),
      btsnooz_buffer_(max_packets_per_buffer),
      qualcomm_debug_log_enabled_(qualcomm_debug_log_enabled),
      snooz_log_life_time_(snooz_log_life_time),
      snooz_log_delete_alarm_interval_(snooz_log_delete_alarm_interval) {
  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(snoop_log_path_, false));
    // delete snooz logs
    delete_btsnoop_files(snooz_log_path_);
  } 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(snoop_log_path_, true));
    // delete snooz logs
    delete_btsnoop_files(snooz_log_path_);
  } else if (btsnoop_mode == kBtSnoopLogModeTruncated) {
    LOG_INFO("Snoop Logs truncated. Limiting to %u", kMaxTruncatedAclPacketSize);
    is_enabled_ = true;
    is_truncated_ = true;
    is_filtered_ = false;
    // delete filtered logs
    delete_btsnoop_files(get_btsnoop_log_path(snoop_log_path_, true));
    // delete snooz logs
    delete_btsnoop_files(snooz_log_path_);
  } 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(snoop_log_path_, true));
    delete_btsnoop_files(get_btsnoop_log_path(snoop_log_path_, false));
  }
  // Add ".filtered" extension if necessary
  snoop_log_path_ = get_btsnoop_log_path(snoop_log_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_last_log_path(snoop_log_path_);

  if (os::FileExists(snoop_log_path_)) {
    if (!os::RenameFile(snoop_log_path_, last_file_path)) {
      LOG_ERROR(
          "Unabled to rename existing snoop log from \"%s\" to \"%s\"",
          snoop_log_path_.c_str(),
          last_file_path.c_str());
    }
  } else {
    LOG_INFO("Previous log file \"%s\" does not exist, skip renaming", snoop_log_path_.c_str());
  }

  mode_t prevmask = umask(0);
  // do not use std::ios::app as we want override the existing file
  btsnoop_ostream_.open(snoop_log_path_, std::ios::binary | std::ios::out);
#ifdef USE_FAKE_TIMERS
  file_creation_time = fake_timerfd_get_clock();
#endif
  if (!btsnoop_ostream_.good()) {
    LOG_ALWAYS_FATAL("Unable to open snoop log at \"%s\", error: \"%s\"", snoop_log_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\"", snoop_log_path_.c_str(), strerror(errno));
  }
  if (!btsnoop_ostream_.flush()) {
    LOG_ERROR("Failed to flush, error: \"%s\"", strerror(errno));
  }
}

void SnoopLogger::Capture(const HciPacket& packet, Direction direction, PacketType type) {
  uint64_t timestamp_us =
      std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch())
          .count();
  std::bitset<32> flags = 0;
  switch (type) {
    case PacketType::CMD:
      flags.set(0, false);
      flags.set(1, true);
      break;
    case PacketType::ACL:
    case PacketType::ISO:
    case PacketType::SCO:
      flags.set(0, direction == Direction::INCOMING);
      flags.set(1, false);
      break;
    case PacketType::EVT:
      flags.set(0, true);
      flags.set(1, true);
      break;
  }
  uint32_t length = packet.size() + /* type byte */ 1;
  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 + kBtSnoopEpochDelta),
                             .type = static_cast<uint8_t>(type)};
  if (is_truncated_ && type == PacketType::ACL) {
    header.length_captured = htonl(std::min(length, kMaxTruncatedAclPacketSize));
  }
  {
    std::lock_guard<std::recursive_mutex> lock(file_mutex_);
    if (!is_enabled_) {
      // btsnoop disabled, log in-memory btsnooz log only
      std::stringstream ss;
      size_t included_length = get_btsnooz_packet_length_to_write(packet, type, qualcomm_debug_log_enabled_);
      header.length_captured = htonl(included_length + /* type byte */ 1);
      if (!ss.write(reinterpret_cast<const char*>(&header), sizeof(PacketHeaderType))) {
        LOG_ERROR("Failed to write packet header for btsnooz, error: \"%s\"", strerror(errno));
      }
      if (!ss.write(reinterpret_cast<const char*>(packet.data()), included_length)) {
        LOG_ERROR("Failed to write packet payload for btsnooz, error: \"%s\"", strerror(errno));
      }
      btsnooz_buffer_.Push(ss.str());
      return;
    }
    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 for btsnoop, error: \"%s\"", strerror(errno));
    }
    if (!btsnoop_ostream_.write(reinterpret_cast<const char*>(packet.data()), packet.size())) {
      LOG_ERROR("Failed to write packet payload for btsnoop, error: \"%s\"", strerror(errno));
    }
    // std::ofstream::flush() pushes user data into kernel memory. The data will be written even if this process
    // crashes. However, data will be lost if there is a kernel panic, which is out of scope of BT snoop log.
    // NOTE: std::ofstream::write() followed by std::ofstream::flush() has similar effect as UNIX write(fd, data, len)
    //       as write() syscall dumps data into kernel memory directly
    if (!btsnoop_ostream_.flush()) {
      LOG_ERROR("Failed to flush, error: \"%s\"", strerror(errno));
    }
  }
}

void SnoopLogger::DumpSnoozLogToFile(const std::vector<std::string>& data) const {
  std::lock_guard<std::recursive_mutex> lock(file_mutex_);
  if (is_enabled_) {
    LOG_DEBUG("btsnoop log is enabled, skip dumping btsnooz log");
    return;
  }

  auto last_file_path = get_last_log_path(snooz_log_path_);

  if (os::FileExists(snooz_log_path_)) {
    if (!os::RenameFile(snooz_log_path_, last_file_path)) {
      LOG_ERROR(
          "Unabled to rename existing snooz log from \"%s\" to \"%s\"",
          snooz_log_path_.c_str(),
          last_file_path.c_str());
    }
  } else {
    LOG_INFO("Previous log file \"%s\" does not exist, skip renaming", snooz_log_path_.c_str());
  }

  mode_t prevmask = umask(0);
  // do not use std::ios::app as we want override the existing file
  std::ofstream btsnooz_ostream(snooz_log_path_, std::ios::binary | std::ios::out);
  if (!btsnooz_ostream.good()) {
    LOG_ALWAYS_FATAL("Unable to open snoop log at \"%s\", error: \"%s\"", snooz_log_path_.c_str(), strerror(errno));
  }
  umask(prevmask);
  if (!btsnooz_ostream.write(reinterpret_cast<const char*>(&kBtSnoopFileHeader), sizeof(FileHeaderType))) {
    LOG_ALWAYS_FATAL("Unable to write file header to \"%s\", error: \"%s\"", snooz_log_path_.c_str(), strerror(errno));
  }
  for (const auto& packet : data) {
    if (!btsnooz_ostream.write(packet.data(), packet.size())) {
      LOG_ERROR("Failed to write packet payload for btsnooz, error: \"%s\"", strerror(errno));
    }
  }
  if (!btsnooz_ostream.flush()) {
    LOG_ERROR("Failed to flush, error: \"%s\"", strerror(errno));
  }
}

void SnoopLogger::ListDependencies(ModuleList* list) const {
  // We have no dependencies
}

void SnoopLogger::Start() {
  std::lock_guard<std::recursive_mutex> lock(file_mutex_);
  if (is_enabled_) {
    OpenNextSnoopLogFile();
  }
  alarm_ = std::make_unique<os::RepeatingAlarm>(GetHandler());
  alarm_->Schedule(
      common::Bind(&delete_old_btsnooz_files, snooz_log_path_, snooz_log_life_time_), snooz_log_delete_alarm_interval_);
}

void SnoopLogger::Stop() {
  std::lock_guard<std::recursive_mutex> lock(file_mutex_);
  LOG_DEBUG("Closing btsnoop log data at %s", snoop_log_path_.c_str());
  CloseCurrentSnoopLogFile();
  // Cancel the alarm
  alarm_->Cancel();
  alarm_.reset();
  // delete any existing snooz logs
  delete_btsnoop_files(snooz_log_path_);
}

DumpsysDataFinisher SnoopLogger::GetDumpsysData(flatbuffers::FlatBufferBuilder* builder) const {
  LOG_DEBUG("Dumping btsnooz log data to %s", snooz_log_path_.c_str());
  DumpSnoozLogToFile(btsnooz_buffer_.Pull());
  return Module::GetDumpsysData(builder);
}

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;
}

size_t SnoopLogger::GetMaxPacketsPerBuffer() {
  // We want to use at most 256 KB memory for btsnooz log for release builds
  // and 512 KB memory for userdebug/eng builds
  auto is_debuggable = os::GetSystemPropertyBool(kIsDebuggableProperty, false);
  size_t btsnooz_max_memory_usage_bytes = (is_debuggable ? 1024 : 256) * 1024;
  // Calculate max number of packets based on max memory usage and max packet size
  return btsnooz_max_memory_usage_bytes / kDefaultBtSnoozMaxBytesPerPacket;
}

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::GetSystemPropertyBool(kIsDebuggableProperty, false);
    if (is_debuggable) {
      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;
}

bool SnoopLogger::IsQualcommDebugLogEnabled() {
  // Check system prop if the soc manufacturer is Qualcomm
  bool qualcomm_debug_log_enabled = false;
  {
    auto soc_manufacturer_prop = os::GetSystemProperty(kSoCManufacturerProperty);
    qualcomm_debug_log_enabled = soc_manufacturer_prop.has_value() &&
                                 common::StringTrim(soc_manufacturer_prop.value()) == kSoCManufacturerQualcomm;
  }
  return qualcomm_debug_log_enabled;
}

const ModuleFactory SnoopLogger::Factory = ModuleFactory([]() {
  return new SnoopLogger(
      os::ParameterProvider::SnoopLogFilePath(),
      os::ParameterProvider::SnoozLogFilePath(),
      GetMaxPacketsPerFile(),
      GetMaxPacketsPerBuffer(),
      GetBtSnoopMode(),
      IsQualcommDebugLogEnabled(),
      kBtSnoozLogLifeTime,
      kBtSnoozLogDeleteRepeatingAlarmInterval);
});

}  // namespace hal
}  // namespace bluetooth