zircon/kernel/platform/ram_mappable_crashlog.cc

// Copyright 2020 The Fuchsia Authors
//
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file or at
// https://opensource.org/licenses/MIT

#include <lib/persistent-debuglog.h>
#include <lib/zbi-format/reboot.h>
#include <platform.h>
#include <stdio.h>

#include <kernel/timer.h>
#include <ktl/algorithm.h>
#include <ktl/limits.h>
#include <ktl/span.h>
#include <platform/ram_mappable_crashlog.h>
#include <ram-crashlog/ram-crashlog.h>
#include <vm/physmap.h>

#include <ktl/enforce.h>

namespace {
FILE NULL_FILE = FILE{[](void*, ktl::string_view str) -> int {
                        DEBUG_ASSERT(str.size() <= ktl::numeric_limits<int>::max());
                        return static_cast<int>(str.size());
                      },
                      nullptr};
}  // namespace

RamMappableCrashlog::RamMappableCrashlog(paddr_t phys, size_t len)
    : crashlog_buffer_(phys && len
                           ? ktl::span<char>{static_cast<char*>(paddr_to_physmap(phys)), len}
                           : ktl::span<char>{}),
      render_target_(crashlog_buffer_.size() > sizeof(ram_crashlog_v1_t)
                         ? crashlog_buffer_.subspan(sizeof(ram_crashlog_v1_t))
                         : ktl::span<char>{}) {
  if (!crashlog_buffer_.empty()) {
    // Go ahead and "recover" the log right now.  All this will do is verify the
    // various CRCs and extract the results if everything checks out.  We don't
    // want to do this more than once.
    log_recovery_result_ =
        ram_crashlog_recover(crashlog_buffer_.data(), crashlog_buffer_.size(), &recovered_log_);
  } else {
    memset(&recovered_log_, 0, sizeof(recovered_log_));
  }
}

void RamMappableCrashlog::Finalize(zircon_crash_reason_t reason, size_t amt) {
  // Whatever the user tells us, the amt of the crashlog render target which was
  // filled cannot exceed the amount that we originally reported, nor can it be
  // larger than what a u32 can hold.
  amt = ktl::min(amt, render_target_.size());
  amt = ktl::min<size_t>(amt, ktl::numeric_limits<uint32_t>::max());

  // The RAM crashlog library will gracefully handle a nullptr or 0 length here;
  // no need to explicitly check that they are valid.
  ram_crashlog_stow(crashlog_buffer_.data(), crashlog_buffer_.size(), render_target_.data(),
                    static_cast<uint32_t>(amt), reason, current_boot_time(), current_mono_time());
}

size_t RamMappableCrashlog::Recover(FILE* tgt) {
  // If the user didn't supply a target FILE to render to, use the NULL_FILE
  // instead so that we compute a proper length for them as we go.
  if (tgt == nullptr) {
    tgt = &NULL_FILE;
  }

  // Create a string representation of the HW reboot reason.
  zbi_hw_reboot_reason_t hw_reason = platform_hw_reboot_reason();
  const char* str_hw_reason;
  char str_hw_reason_buf[16];
  switch (hw_reason) {
    case ZBI_HW_REBOOT_REASON_UNDEFINED:
      str_hw_reason = "UNKNOWN";
      break;
    case ZBI_HW_REBOOT_REASON_COLD:
      str_hw_reason = "COLD BOOT";
      break;
    case ZBI_HW_REBOOT_REASON_WARM:
      str_hw_reason = "WARM BOOT";
      break;
    case ZBI_HW_REBOOT_REASON_BROWNOUT:
      str_hw_reason = "BROWNOUT";
      break;
    case ZBI_HW_REBOOT_REASON_WATCHDOG:
      str_hw_reason = "HW WATCHDOG";
      break;
    default:
      snprintf(str_hw_reason_buf, sizeof(str_hw_reason_buf), "0x%08x",
               static_cast<uint32_t>(hw_reason));
      str_hw_reason = str_hw_reason_buf;
      break;
  }

  // If we failed to recover any crashlog, simply report the size as 0.
  if (log_recovery_result_ != ZX_OK) {
    // Do not bother to log any recovery errors if the log was "corrupt", and we
    // either don't know the HW reboot reason, or we know that the reason is a
    // cold boot.  We don't expect to recover any log during a cold boot, and
    // systems which do not report a HW reboot reason via the ZBI will always
    // just tell us "unknown".
    if (ShouldPrintCrashlogStatus()) {
      if (!((log_recovery_result_ == ZX_ERR_IO_DATA_INTEGRITY) &&
            ((hw_reason == ZBI_HW_REBOOT_REASON_UNDEFINED) ||
             (hw_reason == ZBI_HW_REBOOT_REASON_COLD)))) {
        printf("Crashlog: Failed to recover crashlog.  Result %d, HW Reboot Reason %s\n",
               log_recovery_result_, str_hw_reason);
      }
    }

    return 0;
  }

  // OK, we have a log.  Currently, the log is expected to be nothing but text,
  // so we need to take the structured information we have access to and put it
  // into string form.  This includes:
  //
  // 1) The uptime estimate
  // 2) The runtime estimate
  // 3) The "software" reboot reason.
  // 4) The "hardware" reboot reason (only if given to us by the bootloader).
  // 5) The payload damage indicator (only if there was potential damage to the
  //    payload)
  //
  // The first few lines of text need to be structured so that they can be
  // understood by the crash-log harvester up in userland.  Right now, this is
  // just a loose convention.  Someday, it would be good to pass this data in a
  // much more structured form.
  const recovered_ram_crashlog_t& rlog = recovered_log_;
  const char* str_reason;
  switch (rlog.reason) {
    case ZirconCrashReason::Unknown:
      // If we rebooted spontaneously, check to see if we have some more details
      // provided by way of the bootloader and the HW reboot reason register.
      switch (hw_reason) {
        case ZBI_HW_REBOOT_REASON_BROWNOUT:
        case ZBI_HW_REBOOT_REASON_WATCHDOG:
          str_reason = str_hw_reason;
          break;
        default:
          str_reason = "UNKNOWN";
          break;
      }
      break;
    case ZirconCrashReason::Oom:
      str_reason = "OOM";
      break;
    case ZirconCrashReason::Panic:
      str_reason = "KERNEL PANIC";
      break;
    case ZirconCrashReason::SoftwareWatchdog:
      str_reason = "SW WATCHDOG";
      break;
    case ZirconCrashReason::NoCrash:
      str_reason = "NO CRASH";
      break;
    case ZirconCrashReason::UserspaceRootJobTermination:
      str_reason = "USERSPACE ROOT JOB TERMINATION";
      break;
    default:
      str_reason = nullptr;
      break;
  }

  if (ShouldPrintCrashlogStatus()) {
    // Provide some basic details about the crashlog we recovered in the kernel
    // log.  This can assist in debugging failure in CI/CQ where we might have
    // access to serial logs, but nothing else.
    int64_t uptime_msec = rlog.uptime / ZX_MSEC(1);
    if (rlog.reason == ZirconCrashReason::NoCrash) {
      printf("Crashlog: Clean reboot. Uptime (%" PRId64 ".%03" PRId64 " sec) HW Reason \"%s\"\n",
             uptime_msec / 1000, uptime_msec % 1000, str_hw_reason);
    } else {
      printf("Crashlog: Uptime (%" PRId64 ".%03" PRId64
             " sec) SW Reason \"%s\" HW Reason \"%s\" Payload %s PLen %u\n",
             uptime_msec / 1000, uptime_msec % 1000, str_reason, str_hw_reason,
             rlog.payload_valid ? "valid" : "invalid", rlog.payload_len);
    }
  }

  // First line must give the reboot reason, and be followed by two newlines.
  size_t written = 0;
  written += fprintf(tgt, "ZIRCON REBOOT REASON (%s)\n\n", str_reason);

  // Uptime estimate comes next with a newline between the tag and the actual number
  written += fprintf(tgt, "UPTIME (ms)\n%ld\n", rlog.uptime / ZX_MSEC(1));

  // Runtime estimate comes next with a newline between the tag and the actual number.
  written += fprintf(tgt, "RUNTIME (ms)\n%ld\n", rlog.runtime / ZX_MSEC(1));

  // After this, we are basically just free form text.
  if (str_hw_reason != nullptr) {
    written += fprintf(tgt, "HW REBOOT REASON (%s)\n", str_hw_reason);
  } else {
    written += fprintf(tgt, "HW REBOOT REASON (0x%08x)\n", static_cast<uint32_t>(hw_reason));
  }

  if (rlog.payload_valid == false) {
    written += fprintf(tgt,
                       "WARNING - The following crashlog payload failed length/CRC sanity checks "
                       "and may contain errors!\n");
  }

  if (rlog.payload && rlog.payload_len) {
    tgt->Write(ktl::string_view{static_cast<const char*>(rlog.payload), rlog.payload_len});
    written += rlog.payload_len;
  }

  // Render any persistent dlog we happened to recover
  ktl::string_view dlog = persistent_dlog_get_recovered_log();
  if (dlog.size() > 0) {
    int print_res =
        fprintf(tgt, "Recovered %zu bytes from the persistent debug log\n", dlog.size());
    if (print_res > 0) {
      written += print_res;
    }

    print_res = fprintf(tgt, "=================== BEGIN ===================\n");
    if (print_res > 0) {
      written += print_res;
    }

    written += tgt->Write(dlog);

    print_res = fprintf(tgt, "=================== END ===================\n");
    if (print_res > 0) {
      written += print_res;
    }
  }

  // Report the total length.
  return written + rlog.payload_len;
}

void RamMappableCrashlog::EnableCrashlogUptimeUpdates(bool enabled) {
  Guard<SpinLock, IrqSave> guard{&uptime_updater_lock_};

  if (uptime_updater_enabled_ != enabled) {
    uptime_updater_enabled_ = enabled;
    if (uptime_updater_enabled_) {
      UpdateUptimeLocked();
    } else {
      uptime_updater_timer_.Cancel();
    }
  }
}

void RamMappableCrashlog::UpdateUptimeLocked() {
  if (uptime_updater_enabled_) {
    constexpr zx_duration_t kDefaultUpdateInterval = ZX_SEC(1);

    ram_crashlog_stow(crashlog_buffer_.data(), crashlog_buffer_.size(), nullptr, 0,
                      ZirconCrashReason::Unknown, current_boot_time(), current_mono_time());

    Deadline next_update_time = Deadline::after_mono(
        kDefaultUpdateInterval, {kDefaultUpdateInterval / 2, TIMER_SLACK_CENTER});
    uptime_updater_timer_.Set(
        next_update_time,
        [](Timer*, zx_instant_mono_t now, void* arg) {
          auto thiz = reinterpret_cast<RamMappableCrashlog*>(arg);
          Guard<SpinLock, IrqSave> guard{&thiz->uptime_updater_lock_};
          thiz->UpdateUptimeLocked();
        },
        this);
  }
}