src/developer/debug/shared/logging/debug.cc

// Copyright 2019 The Fuchsia Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "src/developer/debug/shared/logging/debug.h"

#include <lib/syslog/cpp/macros.h>

#include <chrono>
#include <mutex>
#include <set>

#include "src/developer/debug/shared/logging/logging.h"
#include "src/lib/files/path.h"
#include "src/lib/fxl/strings/string_printf.h"

namespace debug_ipc {

namespace {

bool kDebugMode = false;

// This marks the moment SetDebugMode was called.
std::chrono::steady_clock::time_point kStartTime = std::chrono::steady_clock::now();

std::set<LogCategory>& GetLogCategories() {
  static std::set<LogCategory> categories = {LogCategory::kAll};
  return categories;
}

}  // namespace

bool IsDebugModeActive() { return kDebugMode; }

void SetDebugMode(bool activate) { kDebugMode = activate; }

double SecondsSinceStart() {
  return std::chrono::duration<double>(std::chrono::steady_clock::now() - kStartTime).count();
}

const std::set<LogCategory>& GetActiveLogCategories() { return GetLogCategories(); }

void SetLogCategories(std::initializer_list<LogCategory> categories) {
  auto& active_categories = GetLogCategories();
  active_categories.clear();
  for (LogCategory category : categories) {
    active_categories.insert(category);
  }
}

bool IsLogCategoryActive(LogCategory category) {
  if (!IsDebugModeActive())
    return false;

  if (category == LogCategory::kAll)
    return true;

  const auto& active_categories = GetLogCategories();
  if (active_categories.count(LogCategory::kAll) > 0)
    return true;

  return active_categories.count(category) > 0;
}

// Log Tree ----------------------------------------------------------------------------------------

// Log tree works by pusing a log statement when the logging is done but waiting until that block
// is done to pop it out of the stack. By waiting until the whole stack is popped, we can flush the
// logs with a correct log context.
//
// This has several drawbacks though, such as additional context is needed to reconstruct logs in
// case of a crash (backpointer to the log statement object) and that depending on the stack, log
// statements might not appear for a while.

namespace {

// Logs are aranged in a tree that permits going back to the parent.
struct LogEntry {
  LogCategory category = LogCategory::kNone;
  FileLineFunction location;
  std::string msg;
  double start_time = 0;
  double end_time = 0;

  std::vector<std::unique_ptr<LogEntry>> children;
  LogEntry* parent = nullptr;

  // If a statement is valid, it means that it has not been flushed out of the stack, thus the
  // statement is still valid in memory. We can use this backpointer to flush the statement.
  LogStatement* statement = nullptr;
};
inline bool Valid(const LogEntry& entry) { return entry.location.is_valid(); }

LogEntry gRootSlot;
LogEntry* gCurrentSlot = nullptr;

std::mutex gLogMutex;

// Output is dd:hh:mm:ss.<ms>. dd is only showen when non-zero.
std::string SecondsToTimeString(double ds) {
  int total_secs = static_cast<int>(ds);
  int s = total_secs % 60;

  int total_min = total_secs / 60;
  int m = total_min % 60;

  int total_hours = total_min / 60;
  int h = total_hours % 24;

  int d = total_hours / 24;

  int ms = static_cast<int>((ds - total_secs) * 1000);

  // We don't want to add days if it's 0, as it adds noise and it will be rare to have them.
  if (d == 0) {
    return fxl::StringPrintf("%02d:%02d:%02d.%03d", h, m, s, ms);
  } else {
    return fxl::StringPrintf("%02d:%02d:%02d:%02d.%03d", d, h, m, s, ms);
  }
}

// Output is <sec>.<ms> (eg. 32.453).
std::string DurationToString(double start, double end) {
  double diff = end - start;
  int s = static_cast<int>(diff);
  int ms = static_cast<int>((diff - s) * 1000000);

  return fxl::StringPrintf("%03d.%06ds", s, ms);
}

// Format is (depending on whether |entry.location| is valid or not:
// [<time>][<category>]<indent><log msg>    (location invalid).
// [<time>][<category>]<indent>[<function>][<file:line>] <log msg>
std::string LogEntryToStr(const LogEntry& entry, int indent) {
  auto start_time_str = SecondsToTimeString(entry.start_time);
  const char* cat_str = LogCategoryToString(entry.category);

  // No location is only timing information.
  if (!entry.location.is_valid()) {
    return fxl::StringPrintf("[%s][%10s]%*s%s", start_time_str.c_str(), cat_str, indent, "",
                             entry.msg.c_str());
  }

  auto duration_str = DurationToString(entry.start_time, entry.end_time);
  auto file = files::GetBaseName(entry.location.file());
  int line = entry.location.line();
  const char* function = entry.location.function().c_str();

  return fxl::StringPrintf("[%s][%s][%10s]%*s[%s:%d][%s] %s", start_time_str.c_str(),
                           duration_str.c_str(), cat_str, indent, "", file.c_str(), line, function,
                           entry.msg.c_str());
}

// Goes over the logging tree recursively and correctly indents the log messages into |logs|.
void UnwindLogTree(const LogEntry& entry, std::vector<std::string>* logs, int indent = 0) {
  logs->emplace_back(LogEntryToStr(entry, indent));

  for (auto& child : entry.children) {
    UnwindLogTree(*child, logs, indent + 2);
  }
}

// If the log entry is not filled, it means that it's still in the stack. We use the backpointer it
// was to the log statement that generated it to fill it. This normally happens then |PopLogEntry|
// is called, but an exception handler that calls |FlushLogEntries| can also make this happen.
void FillInLogEntryFromStatement(LogEntry* entry) {
  if (Valid(*entry))
    return;

  if (!entry->statement)
    return;

  // Refill the slot with the log statement.
  entry->category = entry->statement->category();
  entry->location = entry->statement->origin();
  entry->msg = entry->statement->GetMsg();
  entry->start_time = entry->statement->start_time();
  entry->end_time = SecondsSinceStart();
  entry->statement = nullptr;
}

void TraverseLogTree(LogEntry* entry, std::vector<std::string>* logs, int indent = 0) {
  FillInLogEntryFromStatement(entry);
  logs->emplace_back(LogEntryToStr(*entry, indent));

  for (auto& child_entry : entry->children) {
    TraverseLogTree(child_entry.get(), logs, indent + 2);
  }
}

}  // namespace

void PushLogEntry(LogStatement* statement) {
  std::lock_guard<std::mutex> lock(gLogMutex);
  // No slot means that it's a new message tree. Use the root.
  if (!gCurrentSlot) {
    gRootSlot = {};
    gCurrentSlot = &gRootSlot;
  } else {
    // Push a child.
    gCurrentSlot->children.push_back(std::make_unique<LogEntry>());
    auto& child = gCurrentSlot->children.back();
    child->parent = gCurrentSlot;
    gCurrentSlot = child.get();
  }

  gCurrentSlot->statement = statement;
}

void PopLogEntry(LogCategory category, const FileLineFunction& location, const std::string& msg,
                 double start_time, double end_time) {
  std::vector<std::string> logs;
  {
    std::lock_guard<std::mutex> lock(gLogMutex);

    // Set the message that's going away to the child.
    gCurrentSlot->category = category;
    gCurrentSlot->location = location;
    gCurrentSlot->msg = msg;
    gCurrentSlot->start_time = start_time;
    gCurrentSlot->end_time = end_time;
    gCurrentSlot->statement = nullptr;

    // While there is still a parent, we're not at the root.
    if (gCurrentSlot->parent) {
      gCurrentSlot = gCurrentSlot->parent;
      return;
    }

    // We tried to pop the root, that means this logging tree is done and we're going to output it
    // and reset everything.
    UnwindLogTree(*gCurrentSlot, &logs);
    gCurrentSlot = nullptr;
  }

  for (auto& log : logs) {
    fprintf(stderr, "\r%s\r\n", log.c_str());
  }
  fflush(stderr);
}

void FlushLogEntries() {
  std::vector<std::string> logs;

  {
    if (!gLogMutex.try_lock())
      return;
    TraverseLogTree(&gRootSlot, &logs);
    gLogMutex.unlock();
  }

  for (auto& log : logs) {
    fprintf(stderr, "\rLOG: %s\r\n", log.c_str());
  }
  fflush(stderr);
}

const char* LogCategoryToString(LogCategory category) {
  switch (category) {
    case LogCategory::kAgent:
      return "Agent";
    case LogCategory::kArchArm64:
      return "arm64";
    case LogCategory::kArchx64:
      return "x64";
    case LogCategory::kBreakpoint:
      return "Breakpoint";
    case LogCategory::kJob:
      return "Job";
    case LogCategory::kMessageLoop:
      return "Loop";
    case LogCategory::kProcess:
      return "Process";
    case LogCategory::kRemoteAPI:
      return "DebugAPI";
    case LogCategory::kSession:
      return "Session";
    case LogCategory::kSetting:
      return "Setting";
    case LogCategory::kTest:
      return "Test";
    case LogCategory::kTiming:
      return "Timing";
    case LogCategory::kThread:
      return "Thread";
    case LogCategory::kWatchpoint:
      return "Watchpoint";
    case LogCategory::kWorkerPool:
      return "WorkerPool";
    case LogCategory::kAll:
      return "All";
    case LogCategory::kNone:
      return "<none>";
  }

  FX_NOTREACHED();
  return "<unknown>";
}

}  // namespace debug_ipc