otautil/logging.cpp

/*
 * Copyright (C) 2016 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 "otautil/logging.h"

#include <dirent.h>
#include <errno.h>
#include <stdio.h>
#include <string.h>
#include <sys/klog.h>
#include <sys/types.h>

#include <algorithm>
#include <memory>
#include <string>

#include <android-base/file.h>
#include <android-base/logging.h>
#include <android-base/parseint.h>
#include <android-base/stringprintf.h>
#include <android-base/unique_fd.h>
#include <private/android_filesystem_config.h> /* for AID_SYSTEM */
#include <private/android_logger.h>            /* private pmsg functions */
#include <selinux/label.h>

#include "otautil/dirutil.h"
#include "otautil/paths.h"
#include "otautil/roots.h"

constexpr const char* LOG_FILE = "/cache/recovery/log";
constexpr const char* LAST_INSTALL_FILE = "/cache/recovery/last_install";
constexpr const char* LAST_KMSG_FILE = "/cache/recovery/last_kmsg";
constexpr const char* LAST_LOG_FILE = "/cache/recovery/last_log";

constexpr const char* LAST_KMSG_FILTER = "recovery/last_kmsg";
constexpr const char* LAST_LOG_FILTER = "recovery/last_log";

constexpr const char* CACHE_LOG_DIR = "/cache/recovery";

static struct selabel_handle* logging_sehandle;

void SetLoggingSehandle(selabel_handle* handle) {
  logging_sehandle = handle;
}

// fopen(3)'s the given file, by mounting volumes and making parent dirs as necessary. Returns the
// file pointer, or nullptr on error.
static FILE* fopen_path(const std::string& path, const char* mode, const selabel_handle* sehandle) {
  if (ensure_path_mounted(path) != 0) {
    LOG(ERROR) << "Can't mount " << path;
    return nullptr;
  }

  // When writing, try to create the containing directory, if necessary. Use generous permissions,
  // the system (init.rc) will reset them.
  if (strchr("wa", mode[0])) {
    mkdir_recursively(path, 0777, true, sehandle);
  }
  return fopen(path.c_str(), mode);
}

void check_and_fclose(FILE* fp, const std::string& name) {
  fflush(fp);
  if (fsync(fileno(fp)) == -1) {
    PLOG(ERROR) << "Failed to fsync " << name;
  }
  if (ferror(fp)) {
    PLOG(ERROR) << "Error in " << name;
  }
  fclose(fp);
}

// close a file, log an error if the error indicator is set
ssize_t logbasename(log_id_t /* id */, char /* prio */, const char* filename, const char* /* buf */,
                    size_t len, void* arg) {
  bool* do_rotate = static_cast<bool*>(arg);
  if (std::string(LAST_KMSG_FILTER).find(filename) != std::string::npos ||
      std::string(LAST_LOG_FILTER).find(filename) != std::string::npos) {
    *do_rotate = true;
  }
  return len;
}

ssize_t logrotate(log_id_t id, char prio, const char* filename, const char* buf, size_t len,
                  void* arg) {
  bool* do_rotate = static_cast<bool*>(arg);
  if (!*do_rotate) {
    return __android_log_pmsg_file_write(id, prio, filename, buf, len);
  }

  std::string name(filename);
  size_t dot = name.find_last_of('.');
  std::string sub = name.substr(0, dot);

  if (std::string(LAST_KMSG_FILTER).find(sub) == std::string::npos &&
      std::string(LAST_LOG_FILTER).find(sub) == std::string::npos) {
    return __android_log_pmsg_file_write(id, prio, filename, buf, len);
  }

  // filename rotation
  if (dot == std::string::npos) {
    name += ".1";
  } else {
    std::string number = name.substr(dot + 1);
    if (!isdigit(number[0])) {
      name += ".1";
    } else {
      size_t i;
      if (!android::base::ParseUint(number, &i)) {
        LOG(ERROR) << "failed to parse uint in " << number;
        return -1;
      }
      name = sub + "." + std::to_string(i + 1);
    }
  }

  return __android_log_pmsg_file_write(id, prio, name.c_str(), buf, len);
}

// Rename last_log -> last_log.1 -> last_log.2 -> ... -> last_log.$max.
// Similarly rename last_kmsg -> last_kmsg.1 -> ... -> last_kmsg.$max.
// Overwrite any existing last_log.$max and last_kmsg.$max.
void rotate_logs(const char* last_log_file, const char* last_kmsg_file) {
  // Logs should only be rotated once.
  static bool rotated = false;
  if (rotated) {
    return;
  }
  rotated = true;

  for (int i = KEEP_LOG_COUNT - 1; i >= 0; --i) {
    std::string old_log = android::base::StringPrintf("%s", last_log_file);
    if (i > 0) {
      old_log += "." + std::to_string(i);
    }
    std::string new_log = android::base::StringPrintf("%s.%d", last_log_file, i + 1);
    // Ignore errors if old_log doesn't exist.
    rename(old_log.c_str(), new_log.c_str());

    std::string old_kmsg = android::base::StringPrintf("%s", last_kmsg_file);
    if (i > 0) {
      old_kmsg += "." + std::to_string(i);
    }
    std::string new_kmsg = android::base::StringPrintf("%s.%d", last_kmsg_file, i + 1);
    rename(old_kmsg.c_str(), new_kmsg.c_str());
  }
}

// Writes content to the current pmsg session.
static ssize_t __pmsg_write(const std::string& filename, const std::string& buf) {
  return __android_log_pmsg_file_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO, filename.c_str(),
                                       buf.data(), buf.size());
}

void copy_log_file_to_pmsg(const std::string& source, const std::string& destination) {
  std::string content;
  android::base::ReadFileToString(source, &content);
  __pmsg_write(destination, content);
}

// How much of the temp log we have copied to the copy in cache.
static off_t tmplog_offset = 0;

void reset_tmplog_offset() {
  tmplog_offset = 0;
}

static void copy_log_file(const std::string& source, const std::string& destination, bool append,
                          const selabel_handle* sehandle) {
  FILE* dest_fp = fopen_path(destination, append ? "ae" : "we", sehandle);
  if (dest_fp == nullptr) {
    PLOG(ERROR) << "Can't open " << destination;
  } else {
    FILE* source_fp = fopen(source.c_str(), "re");
    if (source_fp != nullptr) {
      if (append) {
        fseeko(source_fp, tmplog_offset, SEEK_SET);  // Since last write
      }
      char buf[4096];
      size_t bytes;
      while ((bytes = fread(buf, 1, sizeof(buf), source_fp)) != 0) {
        fwrite(buf, 1, bytes, dest_fp);
      }
      if (append) {
        tmplog_offset = ftello(source_fp);
      }
      check_and_fclose(source_fp, source);
    }
    check_and_fclose(dest_fp, destination);
  }
}

void copy_logs(bool save_current_log, bool has_cache, const selabel_handle* sehandle) {
  // We only rotate and record the log of the current session if explicitly requested. This usually
  // happens after wipes, installation from BCB or menu selections. This is to avoid unnecessary
  // rotation (and possible deletion) of log files, if it does not do anything loggable.
  if (!save_current_log) {
    return;
  }

  // Always write to pmsg, this allows the OTA logs to be caught in `logcat -L`.
  copy_log_file_to_pmsg(Paths::Get().temporary_log_file(), LAST_LOG_FILE);
  copy_log_file_to_pmsg(Paths::Get().temporary_install_file(), LAST_INSTALL_FILE);

  // We can do nothing for now if there's no /cache partition.
  if (!has_cache) {
    return;
  }

  ensure_path_mounted(LAST_LOG_FILE);
  ensure_path_mounted(LAST_KMSG_FILE);
  rotate_logs(LAST_LOG_FILE, LAST_KMSG_FILE);

  // Copy logs to cache so the system can find out what happened.
  copy_log_file(Paths::Get().temporary_log_file(), LOG_FILE, true, sehandle);
  copy_log_file(Paths::Get().temporary_log_file(), LAST_LOG_FILE, false, sehandle);
  copy_log_file(Paths::Get().temporary_install_file(), LAST_INSTALL_FILE, false, sehandle);
  save_kernel_log(LAST_KMSG_FILE);
  chmod(LOG_FILE, 0600);
  chown(LOG_FILE, AID_SYSTEM, AID_SYSTEM);
  chmod(LAST_KMSG_FILE, 0600);
  chown(LAST_KMSG_FILE, AID_SYSTEM, AID_SYSTEM);
  chmod(LAST_LOG_FILE, 0640);
  chmod(LAST_INSTALL_FILE, 0644);
  chown(LAST_INSTALL_FILE, AID_SYSTEM, AID_SYSTEM);
  sync();
}

// Read from kernel log into buffer and write out to file.
void save_kernel_log(const char* destination) {
  int klog_buf_len = klogctl(KLOG_SIZE_BUFFER, 0, 0);
  if (klog_buf_len <= 0) {
    PLOG(ERROR) << "Error getting klog size";
    return;
  }

  std::string buffer(klog_buf_len, 0);
  int n = klogctl(KLOG_READ_ALL, &buffer[0], klog_buf_len);
  if (n == -1) {
    PLOG(ERROR) << "Error in reading klog";
    return;
  }
  buffer.resize(n);
  android::base::WriteStringToFile(buffer, destination);
}

std::vector<saved_log_file> ReadLogFilesToMemory() {
  ensure_path_mounted("/cache");

  struct dirent* de;
  std::unique_ptr<DIR, decltype(&closedir)> d(opendir(CACHE_LOG_DIR), closedir);
  if (!d) {
    if (errno != ENOENT) {
      PLOG(ERROR) << "Failed to opendir " << CACHE_LOG_DIR;
    }
    return {};
  }

  std::vector<saved_log_file> log_files;
  while ((de = readdir(d.get())) != nullptr) {
    if (strncmp(de->d_name, "last_", 5) == 0 || strcmp(de->d_name, "log") == 0) {
      std::string path = android::base::StringPrintf("%s/%s", CACHE_LOG_DIR, de->d_name);

      struct stat sb;
      if (stat(path.c_str(), &sb) != 0) {
        PLOG(ERROR) << "Failed to stat " << path;
        continue;
      }
      // Truncate files to 512kb
      size_t read_size = std::min<size_t>(sb.st_size, 1 << 19);
      std::string data(read_size, '\0');

      android::base::unique_fd log_fd(TEMP_FAILURE_RETRY(open(path.c_str(), O_RDONLY)));
      if (log_fd == -1 || !android::base::ReadFully(log_fd, data.data(), read_size)) {
        PLOG(ERROR) << "Failed to read log file " << path;
        continue;
      }

      log_files.emplace_back(saved_log_file{ path, sb, data });
    }
  }

  return log_files;
}

bool RestoreLogFilesAfterFormat(const std::vector<saved_log_file>& log_files) {
  // Re-create the log dir and write back the log entries.
  if (ensure_path_mounted(CACHE_LOG_DIR) != 0) {
    PLOG(ERROR) << "Failed to mount " << CACHE_LOG_DIR;
    return false;
  }

  if (mkdir_recursively(CACHE_LOG_DIR, 0777, false, logging_sehandle) != 0) {
    PLOG(ERROR) << "Failed to create " << CACHE_LOG_DIR;
    return false;
  }

  for (const auto& log : log_files) {
    if (!android::base::WriteStringToFile(log.data, log.name, log.sb.st_mode, log.sb.st_uid,
                                          log.sb.st_gid)) {
      PLOG(ERROR) << "Failed to write to " << log.name;
    }
  }

  // Any part of the log we'd copied to cache is now gone.
  // Reset the pointer so we copy from the beginning of the temp
  // log.
  reset_tmplog_offset();
  copy_logs(true /* save_current_log */, true /* has_cache */, logging_sehandle);

  return true;
}