debuggerd/libdebuggerd/tombstone.cpp

/*
 * Copyright (C) 2012-2014 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.
 */

#define LOG_TAG "DEBUG"

#include "libdebuggerd/tombstone.h"

#include <dirent.h>
#include <errno.h>
#include <fcntl.h>
#include <inttypes.h>
#include <signal.h>
#include <stddef.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/mman.h>
#include <sys/ptrace.h>
#include <sys/stat.h>
#include <time.h>

#include <memory>
#include <string>

#include <android-base/file.h>
#include <android-base/logging.h>
#include <android-base/properties.h>
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <android-base/unique_fd.h>
#include <android/log.h>
#include <log/log.h>
#include <log/logprint.h>
#include <private/android_filesystem_config.h>
#include <unwindstack/DexFiles.h>
#include <unwindstack/JitDebug.h>
#include <unwindstack/Maps.h>
#include <unwindstack/Memory.h>
#include <unwindstack/Regs.h>
#include <unwindstack/Unwinder.h>

#include "libdebuggerd/backtrace.h"
#include "libdebuggerd/open_files_list.h"
#include "libdebuggerd/utility.h"

using android::base::GetBoolProperty;
using android::base::GetProperty;
using android::base::StringPrintf;
using android::base::unique_fd;

using namespace std::literals::string_literals;

#define STACK_WORDS 16

static void dump_header_info(log_t* log) {
  auto fingerprint = GetProperty("ro.build.fingerprint", "unknown");
  auto revision = GetProperty("ro.revision", "unknown");

  _LOG(log, logtype::HEADER, "Build fingerprint: '%s'\n", fingerprint.c_str());
  _LOG(log, logtype::HEADER, "Revision: '%s'\n", revision.c_str());
  _LOG(log, logtype::HEADER, "ABI: '%s'\n", ABI_STRING);
}

static void dump_timestamp(log_t* log, time_t time) {
  struct tm tm;
  localtime_r(&time, &tm);

  char buf[strlen("1970-01-01 00:00:00+0830") + 1];
  strftime(buf, sizeof(buf), "%F %T%z", &tm);
  _LOG(log, logtype::HEADER, "Timestamp: %s\n", buf);
}

static std::string get_stack_overflow_cause(uint64_t fault_addr, uint64_t sp,
                                            unwindstack::Maps* maps) {
  static constexpr uint64_t kMaxDifferenceBytes = 256;
  uint64_t difference;
  if (sp >= fault_addr) {
    difference = sp - fault_addr;
  } else {
    difference = fault_addr - sp;
  }
  if (difference <= kMaxDifferenceBytes) {
    // The faulting address is close to the current sp, check if the sp
    // indicates a stack overflow.
    // On arm, the sp does not get updated when the instruction faults.
    // In this case, the sp will still be in a valid map, which is the
    // last case below.
    // On aarch64, the sp does get updated when the instruction faults.
    // In this case, the sp will be in either an invalid map if triggered
    // on the main thread, or in a guard map if in another thread, which
    // will be the first case or second case from below.
    unwindstack::MapInfo* map_info = maps->Find(sp);
    if (map_info == nullptr) {
      return "stack pointer is in a non-existent map; likely due to stack overflow.";
    } else if ((map_info->flags & (PROT_READ | PROT_WRITE)) != (PROT_READ | PROT_WRITE)) {
      return "stack pointer is not in a rw map; likely due to stack overflow.";
    } else if ((sp - map_info->start) <= kMaxDifferenceBytes) {
      return "stack pointer is close to top of stack; likely stack overflow.";
    }
  }
  return "";
}

static void dump_probable_cause(log_t* log, const siginfo_t* si, unwindstack::Maps* maps,
                                unwindstack::Regs* regs) {
  std::string cause;
  if (si->si_signo == SIGSEGV && si->si_code == SEGV_MAPERR) {
    if (si->si_addr < reinterpret_cast<void*>(4096)) {
      cause = StringPrintf("null pointer dereference");
    } else if (si->si_addr == reinterpret_cast<void*>(0xffff0ffc)) {
      cause = "call to kuser_helper_version";
    } else if (si->si_addr == reinterpret_cast<void*>(0xffff0fe0)) {
      cause = "call to kuser_get_tls";
    } else if (si->si_addr == reinterpret_cast<void*>(0xffff0fc0)) {
      cause = "call to kuser_cmpxchg";
    } else if (si->si_addr == reinterpret_cast<void*>(0xffff0fa0)) {
      cause = "call to kuser_memory_barrier";
    } else if (si->si_addr == reinterpret_cast<void*>(0xffff0f60)) {
      cause = "call to kuser_cmpxchg64";
    } else {
      cause = get_stack_overflow_cause(reinterpret_cast<uint64_t>(si->si_addr), regs->sp(), maps);
    }
  } else if (si->si_signo == SIGSEGV && si->si_code == SEGV_ACCERR) {
    uint64_t fault_addr = reinterpret_cast<uint64_t>(si->si_addr);
    unwindstack::MapInfo* map_info = maps->Find(fault_addr);
    if (map_info != nullptr && map_info->flags == PROT_EXEC) {
      cause = "execute-only (no-read) memory access error; likely due to data in .text.";
    } else {
      cause = get_stack_overflow_cause(fault_addr, regs->sp(), maps);
    }
  } else if (si->si_signo == SIGSYS && si->si_code == SYS_SECCOMP) {
    cause = StringPrintf("seccomp prevented call to disallowed %s system call %d", ABI_STRING,
                         si->si_syscall);
  }

  if (!cause.empty()) _LOG(log, logtype::HEADER, "Cause: %s\n", cause.c_str());
}

static void dump_signal_info(log_t* log, const ThreadInfo& thread_info,
                             unwindstack::Memory* process_memory) {
  char addr_desc[64];  // ", fault addr 0x1234"
  if (signal_has_si_addr(thread_info.siginfo)) {
    void* addr = thread_info.siginfo->si_addr;
    if (thread_info.siginfo->si_signo == SIGILL) {
      uint32_t instruction = {};
      process_memory->Read(reinterpret_cast<uint64_t>(addr), &instruction, sizeof(instruction));
      snprintf(addr_desc, sizeof(addr_desc), "%p (*pc=%#08x)", addr, instruction);
    } else {
      snprintf(addr_desc, sizeof(addr_desc), "%p", addr);
    }
  } else {
    snprintf(addr_desc, sizeof(addr_desc), "--------");
  }

  char sender_desc[32] = {};  // " from pid 1234, uid 666"
  if (signal_has_sender(thread_info.siginfo, thread_info.pid)) {
    get_signal_sender(sender_desc, sizeof(sender_desc), thread_info.siginfo);
  }

  _LOG(log, logtype::HEADER, "signal %d (%s), code %d (%s%s), fault addr %s\n",
       thread_info.siginfo->si_signo, get_signame(thread_info.siginfo),
       thread_info.siginfo->si_code, get_sigcode(thread_info.siginfo), sender_desc, addr_desc);
}

static void dump_thread_info(log_t* log, const ThreadInfo& thread_info) {
  // Blacklist logd, logd.reader, logd.writer, logd.auditd, logd.control ...
  // TODO: Why is this controlled by thread name?
  if (thread_info.thread_name == "logd" ||
      android::base::StartsWith(thread_info.thread_name, "logd.")) {
    log->should_retrieve_logcat = false;
  }

  _LOG(log, logtype::HEADER, "pid: %d, tid: %d, name: %s  >>> %s <<<\n", thread_info.pid,
       thread_info.tid, thread_info.thread_name.c_str(), thread_info.process_name.c_str());
  _LOG(log, logtype::HEADER, "uid: %d\n", thread_info.uid);
}

static std::string get_addr_string(uint64_t addr) {
  std::string addr_str;
#if defined(__LP64__)
  addr_str = StringPrintf("%08x'%08x",
                          static_cast<uint32_t>(addr >> 32),
                          static_cast<uint32_t>(addr & 0xffffffff));
#else
  addr_str = StringPrintf("%08x", static_cast<uint32_t>(addr));
#endif
  return addr_str;
}

static void dump_abort_message(log_t* log, unwindstack::Memory* process_memory, uint64_t address) {
  if (address == 0) {
    return;
  }

  size_t length;
  if (!process_memory->ReadFully(address, &length, sizeof(length))) {
    _LOG(log, logtype::HEADER, "Failed to read abort message header: %s\n", strerror(errno));
    return;
  }

  // The length field includes the length of the length field itself.
  if (length < sizeof(size_t)) {
    _LOG(log, logtype::HEADER, "Abort message header malformed: claimed length = %zd\n", length);
    return;
  }

  length -= sizeof(size_t);

  // The abort message should be null terminated already, but reserve a spot for NUL just in case.
  std::vector<char> msg(length + 1);
  if (!process_memory->ReadFully(address + sizeof(length), &msg[0], length)) {
    _LOG(log, logtype::HEADER, "Failed to read abort message: %s\n", strerror(errno));
    return;
  }

  _LOG(log, logtype::HEADER, "Abort message: '%s'\n", &msg[0]);
}

static void dump_all_maps(log_t* log, unwindstack::Unwinder* unwinder, uint64_t addr) {
  bool print_fault_address_marker = addr;

  unwindstack::Maps* maps = unwinder->GetMaps();
  _LOG(log, logtype::MAPS,
       "\n"
       "memory map (%zu entr%s):",
       maps->Total(), maps->Total() == 1 ? "y" : "ies");
  if (print_fault_address_marker) {
    if (maps->Total() != 0 && addr < maps->Get(0)->start) {
      _LOG(log, logtype::MAPS, "\n--->Fault address falls at %s before any mapped regions\n",
           get_addr_string(addr).c_str());
      print_fault_address_marker = false;
    } else {
      _LOG(log, logtype::MAPS, " (fault address prefixed with --->)\n");
    }
  } else {
    _LOG(log, logtype::MAPS, "\n");
  }

  std::shared_ptr<unwindstack::Memory>& process_memory = unwinder->GetProcessMemory();

  std::string line;
  for (auto const& map_info : *maps) {
    line = "    ";
    if (print_fault_address_marker) {
      if (addr < map_info->start) {
        _LOG(log, logtype::MAPS, "--->Fault address falls at %s between mapped regions\n",
             get_addr_string(addr).c_str());
        print_fault_address_marker = false;
      } else if (addr >= map_info->start && addr < map_info->end) {
        line = "--->";
        print_fault_address_marker = false;
      }
    }
    line += get_addr_string(map_info->start) + '-' + get_addr_string(map_info->end - 1) + ' ';
    if (map_info->flags & PROT_READ) {
      line += 'r';
    } else {
      line += '-';
    }
    if (map_info->flags & PROT_WRITE) {
      line += 'w';
    } else {
      line += '-';
    }
    if (map_info->flags & PROT_EXEC) {
      line += 'x';
    } else {
      line += '-';
    }
    line += StringPrintf("  %8" PRIx64 "  %8" PRIx64, map_info->offset,
                         map_info->end - map_info->start);
    bool space_needed = true;
    if (!map_info->name.empty()) {
      space_needed = false;
      line += "  " + map_info->name;
      std::string build_id = map_info->GetPrintableBuildID();
      if (!build_id.empty()) {
        line += " (BuildId: " + build_id + ")";
      }
    }
    uint64_t load_bias = map_info->GetLoadBias(process_memory);
    if (load_bias != 0) {
      if (space_needed) {
        line += ' ';
      }
      line += StringPrintf(" (load bias 0x%" PRIx64 ")", load_bias);
    }
    _LOG(log, logtype::MAPS, "%s\n", line.c_str());
  }
  if (print_fault_address_marker) {
    _LOG(log, logtype::MAPS, "--->Fault address falls at %s after any mapped regions\n",
         get_addr_string(addr).c_str());
  }
}

static void print_register_row(log_t* log,
                               const std::vector<std::pair<std::string, uint64_t>>& registers) {
  std::string output;
  for (auto& [name, value] : registers) {
    output += android::base::StringPrintf("  %-3s %0*" PRIx64, name.c_str(),
                                          static_cast<int>(2 * sizeof(void*)),
                                          static_cast<uint64_t>(value));
  }

  _LOG(log, logtype::REGISTERS, "  %s\n", output.c_str());
}

void dump_registers(log_t* log, unwindstack::Regs* regs) {
  // Split lr/sp/pc into their own special row.
  static constexpr size_t column_count = 4;
  std::vector<std::pair<std::string, uint64_t>> current_row;
  std::vector<std::pair<std::string, uint64_t>> special_row;

#if defined(__arm__) || defined(__aarch64__)
  static constexpr const char* special_registers[] = {"ip", "lr", "sp", "pc", "pst"};
#elif defined(__i386__)
  static constexpr const char* special_registers[] = {"ebp", "esp", "eip"};
#elif defined(__x86_64__)
  static constexpr const char* special_registers[] = {"rbp", "rsp", "rip"};
#else
  static constexpr const char* special_registers[] = {};
#endif

  regs->IterateRegisters([log, &current_row, &special_row](const char* name, uint64_t value) {
    auto row = &current_row;
    for (const char* special_name : special_registers) {
      if (strcmp(special_name, name) == 0) {
        row = &special_row;
        break;
      }
    }

    row->emplace_back(name, value);
    if (current_row.size() == column_count) {
      print_register_row(log, current_row);
      current_row.clear();
    }
  });

  if (!current_row.empty()) {
    print_register_row(log, current_row);
  }

  print_register_row(log, special_row);
}

void dump_memory_and_code(log_t* log, unwindstack::Maps* maps, unwindstack::Memory* memory,
                          unwindstack::Regs* regs) {
  regs->IterateRegisters([log, maps, memory](const char* reg_name, uint64_t reg_value) {
    std::string label{"memory near "s + reg_name};
    if (maps) {
      unwindstack::MapInfo* map_info = maps->Find(reg_value);
      if (map_info != nullptr && !map_info->name.empty()) {
        label += " (" + map_info->name + ")";
      }
    }
    dump_memory(log, memory, reg_value, label);
  });
}

static bool dump_thread(log_t* log, unwindstack::Unwinder* unwinder, const ThreadInfo& thread_info,
                        uint64_t abort_msg_address, bool primary_thread) {
  log->current_tid = thread_info.tid;
  if (!primary_thread) {
    _LOG(log, logtype::THREAD, "--- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---\n");
  }
  dump_thread_info(log, thread_info);

  if (thread_info.siginfo) {
    dump_signal_info(log, thread_info, unwinder->GetProcessMemory().get());
    dump_probable_cause(log, thread_info.siginfo, unwinder->GetMaps(), thread_info.registers.get());
  }

  if (primary_thread) {
    dump_abort_message(log, unwinder->GetProcessMemory().get(), abort_msg_address);
  }

  dump_registers(log, thread_info.registers.get());

  // Unwind will mutate the registers, so make a copy first.
  std::unique_ptr<unwindstack::Regs> regs_copy(thread_info.registers->Clone());
  unwinder->SetRegs(regs_copy.get());
  unwinder->Unwind();
  if (unwinder->NumFrames() == 0) {
    _LOG(log, logtype::THREAD, "Failed to unwind");
  } else {
    _LOG(log, logtype::BACKTRACE, "\nbacktrace:\n");
    log_backtrace(log, unwinder, "    ");
  }

  if (primary_thread) {
    unwindstack::Maps* maps = unwinder->GetMaps();
    dump_memory_and_code(log, maps, unwinder->GetProcessMemory().get(),
                         thread_info.registers.get());
    if (maps != nullptr) {
      uint64_t addr = 0;
      siginfo_t* si = thread_info.siginfo;
      if (signal_has_si_addr(si)) {
        addr = reinterpret_cast<uint64_t>(si->si_addr);
      }
      dump_all_maps(log, unwinder, addr);
    }
  }

  log->current_tid = log->crashed_tid;
  return true;
}

// Reads the contents of the specified log device, filters out the entries
// that don't match the specified pid, and writes them to the tombstone file.
//
// If "tail" is non-zero, log the last "tail" number of lines.
static EventTagMap* g_eventTagMap = NULL;

static void dump_log_file(log_t* log, pid_t pid, const char* filename, unsigned int tail) {
  bool first = true;
  logger_list* logger_list;

  if (!log->should_retrieve_logcat) {
    return;
  }

  logger_list = android_logger_list_open(
      android_name_to_log_id(filename), ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, tail, pid);

  if (!logger_list) {
    ALOGE("Unable to open %s: %s\n", filename, strerror(errno));
    return;
  }

  while (true) {
    log_msg log_entry;
    ssize_t actual = android_logger_list_read(logger_list, &log_entry);

    if (actual < 0) {
      if (actual == -EINTR) {
        // interrupted by signal, retry
        continue;
      } else if (actual == -EAGAIN) {
        // non-blocking EOF; we're done
        break;
      } else {
        ALOGE("Error while reading log: %s\n", strerror(-actual));
        break;
      }
    } else if (actual == 0) {
      ALOGE("Got zero bytes while reading log: %s\n", strerror(errno));
      break;
    }

    // NOTE: if you ALOGV something here, this will spin forever,
    // because you will be writing as fast as you're reading.  Any
    // high-frequency debug diagnostics should just be written to
    // the tombstone file.

    if (first) {
      _LOG(log, logtype::LOGS, "--------- %slog %s\n",
        tail ? "tail end of " : "", filename);
      first = false;
    }

    // Msg format is: <priority:1><tag:N>\0<message:N>\0
    //
    // We want to display it in the same format as "logcat -v threadtime"
    // (although in this case the pid is redundant).
    char timeBuf[32];
    time_t sec = static_cast<time_t>(log_entry.entry.sec);
    struct tm tmBuf;
    struct tm* ptm;
    ptm = localtime_r(&sec, &tmBuf);
    strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);

    if (log_entry.id() == LOG_ID_EVENTS) {
      if (!g_eventTagMap) {
        g_eventTagMap = android_openEventTagMap(nullptr);
      }
      AndroidLogEntry e;
      char buf[512];
      if (android_log_processBinaryLogBuffer(&log_entry.entry, &e, g_eventTagMap, buf,
                                             sizeof(buf)) == 0) {
        _LOG(log, logtype::LOGS, "%s.%03d %5d %5d %c %-8.*s: %s\n", timeBuf,
             log_entry.entry.nsec / 1000000, log_entry.entry.pid, log_entry.entry.tid, 'I',
             (int)e.tagLen, e.tag, e.message);
      }
      continue;
    }

    char* msg = log_entry.msg();
    if (msg == nullptr) {
      continue;
    }
    unsigned char prio = msg[0];
    char* tag = msg + 1;
    msg = tag + strlen(tag) + 1;

    // consume any trailing newlines
    char* nl = msg + strlen(msg) - 1;
    while (nl >= msg && *nl == '\n') {
      *nl-- = '\0';
    }

    static const char* kPrioChars = "!.VDIWEFS";
    char prioChar = (prio < strlen(kPrioChars) ? kPrioChars[prio] : '?');

    // Look for line breaks ('\n') and display each text line
    // on a separate line, prefixed with the header, like logcat does.
    do {
      nl = strchr(msg, '\n');
      if (nl != nullptr) {
        *nl = '\0';
        ++nl;
      }

      _LOG(log, logtype::LOGS, "%s.%03d %5d %5d %c %-8s: %s\n", timeBuf,
           log_entry.entry.nsec / 1000000, log_entry.entry.pid, log_entry.entry.tid, prioChar, tag,
           msg);
    } while ((msg = nl));
  }

  android_logger_list_free(logger_list);
}

// Dumps the logs generated by the specified pid to the tombstone, from both
// "system" and "main" log devices.  Ideally we'd interleave the output.
static void dump_logs(log_t* log, pid_t pid, unsigned int tail) {
  if (pid == getpid()) {
    // Cowardly refuse to dump logs while we're running in-process.
    return;
  }

  dump_log_file(log, pid, "system", tail);
  dump_log_file(log, pid, "main", tail);
}

void engrave_tombstone_ucontext(int tombstone_fd, uint64_t abort_msg_address, siginfo_t* siginfo,
                                ucontext_t* ucontext) {
  pid_t uid = getuid();
  pid_t pid = getpid();
  pid_t tid = gettid();

  log_t log;
  log.current_tid = tid;
  log.crashed_tid = tid;
  log.tfd = tombstone_fd;
  log.amfd_data = nullptr;

  char thread_name[16];
  char process_name[128];

  read_with_default("/proc/self/comm", thread_name, sizeof(thread_name), "<unknown>");
  read_with_default("/proc/self/cmdline", process_name, sizeof(process_name), "<unknown>");

  std::unique_ptr<unwindstack::Regs> regs(
      unwindstack::Regs::CreateFromUcontext(unwindstack::Regs::CurrentArch(), ucontext));

  std::map<pid_t, ThreadInfo> threads;
  threads[gettid()] = ThreadInfo{
      .registers = std::move(regs),
      .uid = uid,
      .tid = tid,
      .thread_name = thread_name,
      .pid = pid,
      .process_name = process_name,
      .siginfo = siginfo,
  };

  unwindstack::UnwinderFromPid unwinder(kMaxFrames, pid);
  if (!unwinder.Init(unwindstack::Regs::CurrentArch())) {
    LOG(FATAL) << "Failed to init unwinder object.";
  }

  engrave_tombstone(unique_fd(dup(tombstone_fd)), &unwinder, threads, tid, abort_msg_address,
                    nullptr, nullptr);
}

void engrave_tombstone(unique_fd output_fd, unwindstack::Unwinder* unwinder,
                       const std::map<pid_t, ThreadInfo>& threads, pid_t target_thread,
                       uint64_t abort_msg_address, OpenFilesList* open_files,
                       std::string* amfd_data) {
  // don't copy log messages to tombstone unless this is a dev device
  bool want_logs = android::base::GetBoolProperty("ro.debuggable", false);

  log_t log;
  log.current_tid = target_thread;
  log.crashed_tid = target_thread;
  log.tfd = output_fd.get();
  log.amfd_data = amfd_data;

  _LOG(&log, logtype::HEADER, "*** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***\n");
  dump_header_info(&log);
  dump_timestamp(&log, time(nullptr));

  auto it = threads.find(target_thread);
  if (it == threads.end()) {
    LOG(FATAL) << "failed to find target thread";
  }
  dump_thread(&log, unwinder, it->second, abort_msg_address, true);

  if (want_logs) {
    dump_logs(&log, it->second.pid, 50);
  }

  for (auto& [tid, thread_info] : threads) {
    if (tid == target_thread) {
      continue;
    }

    dump_thread(&log, unwinder, thread_info, 0, false);
  }

  if (open_files) {
    _LOG(&log, logtype::OPEN_FILES, "\nopen files:\n");
    dump_open_files_list(&log, *open_files, "    ");
  }

  if (want_logs) {
    dump_logs(&log, it->second.pid, 0);
  }
}