xref: /external/perfetto/src/trace_processor/importers/android_bugreport/android_bugreport_parser.cc

/*
 * Copyright (C) 2022 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 "src/trace_processor/importers/android_bugreport/android_bugreport_parser.h"

#include <algorithm>
#include <cstddef>
#include <optional>
#include <string>
#include <vector>

#include "perfetto/base/logging.h"
#include "perfetto/base/status.h"
#include "perfetto/ext/base/string_utils.h"
#include "protos/perfetto/common/builtin_clock.pbzero.h"
#include "src/trace_processor/importers/android_bugreport/android_log_parser.h"
#include "src/trace_processor/importers/common/clock_tracker.h"
#include "src/trace_processor/importers/common/process_tracker.h"
#include "src/trace_processor/types/trace_processor_context.h"
#include "src/trace_processor/util/zip_reader.h"

namespace perfetto {
namespace trace_processor {
namespace {
const util::ZipFile* FindBugReportFile(
    const std::vector<util::ZipFile>& zip_file_entries) {
  for (const auto& zf : zip_file_entries) {
    if (base::StartsWith(zf.name(), "bugreport-") &&
        base::EndsWith(zf.name(), ".txt")) {
      return &zf;
    }
  }
  return nullptr;
}

std::optional<int32_t> ExtractYearFromBugReportFilename(
    const std::string& filename) {
  // Typical name: "bugreport-product-TP1A.220623.001-2022-06-24-16-24-37.txt".
  auto year_str =
      filename.substr(filename.size() - strlen("2022-12-31-23-59-00.txt"), 4);
  return base::StringToInt32(year_str);
}

}  // namespace

// static
bool AndroidBugreportParser::IsAndroidBugReport(
    const std::vector<util::ZipFile>& zip_file_entries) {
  if (const util::ZipFile* file = FindBugReportFile(zip_file_entries);
      file != nullptr) {
    return ExtractYearFromBugReportFilename(file->name()).has_value();
  }

  return false;
}

// static
util::Status AndroidBugreportParser::Parse(
    TraceProcessorContext* context,
    std::vector<util::ZipFile> zip_file_entries) {
  return AndroidBugreportParser(context, std::move(zip_file_entries))
      .ParseImpl();
}

AndroidBugreportParser::AndroidBugreportParser(
    TraceProcessorContext* context,
    std::vector<util::ZipFile> zip_file_entries)
    : context_(context), zip_file_entries_(std::move(zip_file_entries)) {}

AndroidBugreportParser::~AndroidBugreportParser() = default;

util::Status AndroidBugreportParser::ParseImpl() {
  // All logs in Android bugreports use wall time (which creates problems
  // in case of early boot events before NTP kicks in, which get emitted as
  // 1970), but that is the state of affairs.
  context_->clock_tracker->SetTraceTimeClock(
      protos::pbzero::BUILTIN_CLOCK_REALTIME);
  if (!DetectYearAndBrFilename()) {
    context_->storage->IncrementStats(stats::android_br_parse_errors);
    return base::ErrStatus("Zip file does not contain bugreport file.");
  }

  ParsePersistentLogcat();
  ParseDumpstateTxt();
  SortAndStoreLogcat();
  return base::OkStatus();
}

void AndroidBugreportParser::ParseDumpstateTxt() {
  PERFETTO_CHECK(dumpstate_file_);
  // Dumpstate is organized in a two level hierarchy, beautifully flattened into
  // one text file with load bearing ----- markers:
  // 1. Various dumpstate sections, examples:
  // ```
  //   ------ DUMPSYS CRITICAL (/system/bin/dumpsys) ------
  //   ...
  //   ------ SYSTEM LOG (logcat -v threadtime -v printable -v uid) ------
  //   ...
  //   ------ IPTABLES (iptables -L -nvx) ------
  //   ...
  //   ------ DUMPSYS HIGH (/system/bin/dumpsys) ------
  //   ...
  //   ------ DUMPSYS (/system/bin/dumpsys) ------
  // ```
  //
  // 2. Within the "------ DUMPSYS" section (note dumpsys != dumpstate), there
  //    are multiple services. Note that there are at least 3 DUMPSYS sections
  //    (CRITICAL, HIGH and default), with multiple services in each:
  // ```
  //    ------ DUMPSYS (/system/bin/dumpsys) ------
  // DUMP OF SERVICE activity:
  // ...
  // ---------------------------------------------------------------------------
  // DUMP OF SERVICE input_method:
  // ...
  // ---------------------------------------------------------------------------
  // ```
  // Here we put each line in a dedicated table, android_dumpstate, keeping
  // track of the dumpstate `section` and dumpsys `service`.
  AndroidLogParser log_parser(br_year_, context_->storage.get());
  StringId section_id = StringId::Null();  // The current dumpstate section.
  StringId service_id = StringId::Null();  // The current dumpsys service.
  static constexpr size_t npos = base::StringView::npos;
  enum { OTHER = 0, DUMPSYS, LOG } cur_sect = OTHER;
  dumpstate_file_->DecompressLines(
      [&](const std::vector<base::StringView>& lines) {
        // Optimization for ParseLogLines() below. Avoids ctor/dtor-ing a new
        // vector on every line.
        std::vector<base::StringView> log_line(1);
        for (const base::StringView& line : lines) {
          if (line.StartsWith("------ ") && line.EndsWith(" ------")) {
            // These lines mark the beginning and end of dumpstate sections:
            // ------ DUMPSYS CRITICAL (/system/bin/dumpsys) ------
            // ------ 0.356s was the duration of 'DUMPSYS CRITICAL' ------
            base::StringView section = line.substr(7);
            section = section.substr(0, section.size() - 7);
            bool end_marker = section.find("was the duration of") != npos;
            service_id = StringId::Null();
            if (end_marker) {
              section_id = StringId::Null();
            } else {
              section_id = context_->storage->InternString(section);
              cur_sect = OTHER;
              if (section.StartsWith("DUMPSYS")) {
                cur_sect = DUMPSYS;
              } else if (section.StartsWith("SYSTEM LOG") ||
                         section.StartsWith("EVENT LOG") ||
                         section.StartsWith("RADIO LOG")) {
                // KERNEL LOG is deliberately omitted because SYSTEM LOG is a
                // superset. KERNEL LOG contains all dupes.
                cur_sect = LOG;
              } else if (section.StartsWith("BLOCK STAT")) {
                // Coalesce all the block stats into one section. Otherwise they
                // pollute the table with one section per block device.
                section_id = context_->storage->InternString("BLOCK STAT");
              }
            }
            continue;
          }
          // Skip end marker lines for dumpsys sections.
          if (cur_sect == DUMPSYS && line.StartsWith("--------- ") &&
              line.find("was the duration of dumpsys") != npos) {
            service_id = StringId::Null();
            continue;
          }
          if (cur_sect == DUMPSYS && service_id.is_null() &&
              line.StartsWith(
                  "----------------------------------------------")) {
            continue;
          }
          if (cur_sect == DUMPSYS && line.StartsWith("DUMP OF SERVICE")) {
            // DUMP OF SERVICE [CRITICAL|HIGH] ServiceName:
            base::StringView svc = line.substr(line.rfind(' ') + 1);
            svc = svc.substr(0, svc.size() - 1);
            service_id = context_->storage->InternString(svc);
          } else if (cur_sect == LOG) {
            // Parse the non-persistent logcat and append to `log_events_`,
            // together with the persistent one previously parsed by
            // ParsePersistentLogcat(). Skips entries that are already seen in
            // the persistent logcat, handling us vs ms truncation.
            PERFETTO_DCHECK(log_line.size() == 1);
            log_line[0] = line;
            log_parser.ParseLogLines(log_line, &log_events_,
                                     log_events_last_sorted_idx_);
          }

          if (build_fpr_.empty() && line.StartsWith("Build fingerprint:")) {
            build_fpr_ = line.substr(20, line.size() - 20).ToStdString();
          }

          // Append the line to the android_dumpstate table.
          context_->storage->mutable_android_dumpstate_table()->Insert(
              {section_id, service_id, context_->storage->InternString(line)});
        }
      });
}

void AndroidBugreportParser::ParsePersistentLogcat() {
  // 1. List logcat files in reverse timestmap order (old to most recent).
  // 2. Decode events from log lines into a vector. Dedupe and intern strings.
  // 3. Globally sort all extracted events.
  // 4. Insert into the android_logs table.

  AndroidLogParser log_parser(br_year_, context_->storage.get());

  // Sort files to ease the job of the subsequent line-based sort. Unfortunately
  // lines within each file are not 100% timestamp-ordered, due to things like
  // kernel messages where log time != event time.
  std::vector<std::pair<uint64_t, const util::ZipFile*>> log_files;
  for (const util::ZipFile& zf : zip_file_entries_) {
    if (base::StartsWith(zf.name(), "FS/data/misc/logd/logcat") &&
        !base::EndsWith(zf.name(), "logcat.id")) {
      log_files.push_back(std::make_pair(zf.GetDatetime(), &zf));
    }
  }

  std::sort(log_files.begin(), log_files.end());

  // Push all events into the AndroidLogParser. It will take care of string
  // interning into the pool. Appends entries into `log_events`.
  for (const auto& log_file : log_files) {
    log_file.second->DecompressLines(
        [&](const std::vector<base::StringView>& lines) {
          log_parser.ParseLogLines(lines, &log_events_);
        });
  }

  // Do an initial sorting pass. This is not the final sorting because we
  // haven't ingested the latest logs from dumpstate yet. But we need this sort
  // to be able to de-dupe the same lines showing both in dumpstate and in the
  // persistent log.
  SortLogEvents();
}

void AndroidBugreportParser::SortAndStoreLogcat() {
  // Sort the union of all log events parsed from both /data/misc/logd
  // (persistent logcat on disk) and the dumpstate file (last in-memory logcat).
  // Before the std::stable_sort, entries in `log_events_` are already "mostly"
  // sorted, because we processed files in order (see notes above about kernel
  // logs on why we need a final sort here).
  // We need stable-sort to preserve FIFO-ness of events emitted at the same
  // time, logcat is not granular enough (us for persistent, ms for dumpstate).
  SortLogEvents();

  // Insert the globally sorted events into the android_logs table.
  for (const auto& e : log_events_) {
    UniquePid utid = context_->process_tracker->UpdateThread(e.tid, e.pid);
    context_->storage->mutable_android_log_table()->Insert(
        {e.ts, utid, e.prio, e.tag, e.msg});
  }
}

// Populates the `year_` field from the bugreport-xxx.txt file name.
// This is because logcat events have only the month and day.
// This is obviously bugged for cases of bugreports collected across new year
// but we'll live with that.
bool AndroidBugreportParser::DetectYearAndBrFilename() {
  const util::ZipFile* br_file = FindBugReportFile(zip_file_entries_);
  if (!br_file) {
    PERFETTO_ELOG("Could not find bugreport-*.txt in the zip file");
    return false;
  }

  std::optional<int32_t> year =
      ExtractYearFromBugReportFilename(br_file->name());
  if (!year.has_value()) {
    PERFETTO_ELOG("Could not parse the year from %s", br_file->name().c_str());
    return false;
  }
  br_year_ = *year;
  dumpstate_file_ = br_file;
  return true;
}

void AndroidBugreportParser::SortLogEvents() {
  std::stable_sort(log_events_.begin(), log_events_.end());
  log_events_last_sorted_idx_ = log_events_.size();
}

}  // namespace trace_processor
}  // namespace perfetto