sdk/lib/syslog/cpp/logging_backend_fuchsia.cc

// Copyright 2020 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 <assert.h>
#include <fuchsia/diagnostics/stream/cpp/fidl.h>
#include <fuchsia/logger/cpp/fidl.h>
#include <lib/fdio/directory.h>
#include <lib/fdio/fd.h>
#include <lib/fdio/fdio.h>
#include <lib/fit/optional.h>
#include <lib/fit/variant.h>
#include <lib/syslog/cpp/log_level.h>
#include <lib/syslog/cpp/logging_backend.h>
#include <lib/syslog/cpp/logging_backend_fuchsia_globals.h>
#include <lib/syslog/streams/cpp/encode.h>
#include <lib/zx/channel.h>
#include <lib/zx/process.h>

#include <fstream>
#include <iostream>
#include <sstream>

#include "lib/syslog/streams/cpp/fields.h"
#include "logging_backend_fuchsia_private.h"
#include "macros.h"

namespace syslog_backend {

using log_word_t = uint64_t;

zx_koid_t GetKoid(zx_handle_t handle) {
  zx_info_handle_basic_t info;
  zx_status_t status =
      zx_object_get_info(handle, ZX_INFO_HANDLE_BASIC, &info, sizeof(info), nullptr, nullptr);
  return status == ZX_OK ? info.koid : ZX_KOID_INVALID;
}

static zx_koid_t pid = GetKoid(zx_process_self());
static thread_local zx_koid_t tid = GetCurrentThreadKoid();

// Represents a slice of a buffer of type T.
template <typename T>
class DataSlice {
 public:
  DataSlice(T* ptr, size_t size) : ptr_(ptr), size_(size) {}

  T& operator[](size_t offset) {
    assert(offset < size_);
    return ptr_[offset];
  }

  const T& operator[](size_t offset) const {
    assert(offset < size_);
    return ptr_[offset];
  }

  size_t size() { return size_; }

  T* data() { return ptr_; }

 private:
  T* ptr_;
  size_t size_;
};

static DataSlice<const char> SliceFromString(const std::string& string) {
  return DataSlice<const char>(string.data(), string.size());
}

template <typename T, size_t size>
static DataSlice<const T> SliceFromArray(const T (&array)[size]) {
  return DataSlice<const T>(array, size);
}

template <size_t size>
static DataSlice<const char> SliceFromArray(const char (&array)[size]) {
  return DataSlice<const char>(array, size - 1);
}

static constexpr int WORD_SIZE = sizeof(log_word_t);  // See sdk/lib/syslog/streams/cpp/encode.cc
class DataBuffer {
 public:
  static constexpr auto kBufferSize = (1 << 15) / WORD_SIZE;
  void Write(const log_word_t* data, size_t length) {
    assert(cursor_ + length < kBufferSize);
    for (size_t i = 0; i < length; i++) {
      buffer_[cursor_ + i] = data[i];
    }
    cursor_ += length;
  }

  size_t WritePadded(const void* msg, size_t length) {
    assert(cursor_ + length < kBufferSize);
    auto retval = WritePaddedInternal(buffer_ + cursor_, msg, length);
    cursor_ += retval;
    return retval;
  }

  template <typename T>
  void Write(const T& data) {
    static_assert(sizeof(T) >= sizeof(log_word_t));
    static_assert(alignof(T) >= sizeof(log_word_t));
    Write(reinterpret_cast<const log_word_t*>(&data), sizeof(T) / sizeof(log_word_t));
  }

  DataSlice<log_word_t> GetSlice() { return DataSlice<log_word_t>(buffer_, cursor_); }

 private:
  size_t cursor_ = 0;
  log_word_t buffer_[kBufferSize];
};

struct RecordState {
  // Header of the record itself
  uint64_t* header;
  syslog::LogSeverity log_severity;
  ::fuchsia::diagnostics::Severity severity;
  // arg_size in words
  size_t arg_size = 0;
  // key_size in bytes
  size_t current_key_size = 0;
  // Header of the current argument being encoded
  uint64_t* current_header_position = 0;
  uint32_t dropped_count = 0;
  // Current position (in 64-bit words) into the buffer.
  size_t cursor = 0;
  // True if encoding was successful, false otherwise
  bool encode_success = true;
  static RecordState* CreatePtr(LogBuffer* buffer) {
    return reinterpret_cast<RecordState*>(&buffer->record_state);
  }
  size_t PtrToIndex(void* ptr) {
    return reinterpret_cast<size_t>(static_cast<uint8_t*>(ptr)) - reinterpret_cast<size_t>(header);
  }
};
static_assert(sizeof(RecordState) <= sizeof(LogBuffer::record_state));
static_assert(std::alignment_of<RecordState>() == sizeof(uint64_t));

// Used for accessing external data buffers provided by clients.
// Used by the Encoder to do in-place encoding of data
class ExternalDataBuffer {
 public:
  explicit ExternalDataBuffer(LogBuffer* buffer)
      : buffer_(&buffer->data[0]),
        capacity_((sizeof(buffer->data) - sizeof(buffer->record_state))),
        cursor_(RecordState::CreatePtr(buffer)->cursor) {}

  ExternalDataBuffer(log_word_t* data, size_t length, size_t& cursor)
      : buffer_(data), capacity_(length), cursor_(cursor) {}
  __WARN_UNUSED_RESULT bool Write(const log_word_t* data, size_t length) {
    if (cursor_ + length >= capacity_) {
      return false;
    }
    for (size_t i = 0; i < length; i++) {
      buffer_[cursor_ + i] = data[i];
    }
    cursor_ += length;
    return true;
  }

  __WARN_UNUSED_RESULT bool WritePadded(const void* msg, size_t word_count, size_t* written) {
    assert(written != nullptr);
    if (cursor_ + word_count >= capacity_) {
      return false;
    }
    auto retval = WritePaddedInternal(buffer_ + cursor_, msg, word_count);
    cursor_ += retval;
    *written = retval;
    return true;
  }

  template <typename T>
  __WARN_UNUSED_RESULT bool Write(const T& data) {
    static_assert(sizeof(T) >= sizeof(log_word_t));
    static_assert(alignof(T) >= sizeof(log_word_t));
    return Write(reinterpret_cast<const log_word_t*>(&data), sizeof(T) / sizeof(log_word_t));
  }

  uint64_t* data() { return buffer_ + cursor_; }

  DataSlice<log_word_t> GetSlice() { return DataSlice<log_word_t>(buffer_, cursor_); }

 private:
  // Start of buffer
  log_word_t* buffer_ = nullptr;
  // Capacity (in words)
  __UNUSED size_t capacity_ = 0;
  // Current location in buffer (in words)
  size_t& cursor_;
};

template <typename T>
class Encoder {
 public:
  explicit Encoder(T& buffer) { buffer_ = &buffer; }

  void Begin(RecordState& state, zx_time_t timestamp, ::fuchsia::diagnostics::Severity severity) {
    state.severity = severity;
    state.header = buffer_->data();
    log_word_t empty_header = 0;
    state.encode_success &= buffer_->Write(empty_header);
    state.encode_success &= buffer_->Write(timestamp);
  }

  void FlushPreviousArgument(RecordState& state) { state.arg_size = 0; }

  void AppendArgumentKey(RecordState& state, DataSlice<const char> key) {
    FlushPreviousArgument(state);
    auto header_position = buffer_->data();
    log_word_t empty_header = 0;
    state.encode_success &= buffer_->Write(empty_header);
    size_t s_size = 0;
    state.encode_success &= buffer_->WritePadded(key.data(), key.size(), &s_size);
    state.arg_size = s_size + 1;  // offset by 1 for the header
    state.current_key_size = key.size();
    state.current_header_position = header_position;
  }

  uint64_t ComputeArgHeader(RecordState& state, int type, uint64_t value_ref = 0) {
    return ArgumentFields::Type::Make(type) | ArgumentFields::SizeWords::Make(state.arg_size) |
           ArgumentFields::NameRefVal::Make(state.current_key_size) |
           ArgumentFields::NameRefMSB::Make(state.current_key_size > 0 ? 1 : 0) |
           ArgumentFields::ValueRef::Make(value_ref) | ArgumentFields::Reserved::Make(0);
  }

  void AppendArgumentValue(RecordState& state, int64_t value) {
    int type = 3;
    state.encode_success &= buffer_->Write(value);
    state.arg_size++;
    *state.current_header_position = ComputeArgHeader(state, type);
  }

  void AppendArgumentValue(RecordState& state, uint64_t value) {
    int type = 4;
    state.encode_success &= buffer_->Write(value);
    state.arg_size++;
    *state.current_header_position = ComputeArgHeader(state, type);
  }

  void AppendArgumentValue(RecordState& state, double value) {
    int type = 5;
    state.encode_success &= buffer_->Write(value);
    state.arg_size++;
    *state.current_header_position = ComputeArgHeader(state, type);
  }

  void AppendArgumentValue(RecordState& state, DataSlice<const char> string) {
    int type = 6;
    size_t written = 0;
    state.encode_success &= buffer_->WritePadded(string.data(), string.size(), &written);
    state.arg_size += written;
    *state.current_header_position =
        ComputeArgHeader(state, type, string.size() > 0 ? (1 << 15) | string.size() : 0);
  }

  void End(RecordState& state) {
    // See src/lib/diagnostics/stream/rust/src/lib.rs
    constexpr auto kTracingFormatLogRecordType = 9;
    FlushPreviousArgument(state);
    uint64_t header =
        HeaderFields::Type::Make(kTracingFormatLogRecordType) |
        HeaderFields::SizeWords::Make(static_cast<size_t>(buffer_->data() - state.header)) |
        HeaderFields::Reserved::Make(0) | HeaderFields::Severity::Make(state.severity);
    *state.header = header;
  }

 private:
  T* buffer_;
};

const size_t kMaxTags = 4;  // Legacy from ulib/syslog. Might be worth rethinking.
// Compiler thinks this is unused even though WriteLogToSocket uses it.
__UNUSED const char kMessageFieldName[] = "message";
const char kPidFieldName[] = "pid";
const char kTidFieldName[] = "tid";
const char kDroppedLogsFieldName[] = "dropped_logs";
const char kTagFieldName[] = "tag";
const char kFileFieldName[] = "file";
const char kLineFieldName[] = "line";

class LogState {
 public:
  static void Set(const syslog::LogSettings& settings);
  static void Set(const syslog::LogSettings& settings,
                  const std::initializer_list<std::string>& tags);
  static const LogState& Get();

  syslog::LogSeverity min_severity() const { return min_severity_; }

  template <typename T>
  void WriteLog(syslog::LogSeverity severity, const char* file_name, unsigned int line,
                const char* tag, const char* condition, const T& msg) const;
  const std::string* tags() const { return tags_; }
  size_t tag_count() const { return num_tags_; }
  // Allowed to be const because descriptor_ is mutable
  fit::variant<zx::socket, std::ofstream>& descriptor() const { return descriptor_; }

 private:
  LogState(const syslog::LogSettings& settings, const std::initializer_list<std::string>& tags);
  bool WriteLogToFile(std::ofstream* file_ptr, zx_time_t time, zx_koid_t pid, zx_koid_t tid,
                      syslog::LogSeverity severity, const char* file_name, unsigned int line,
                      const char* tag, const char* condition, const std::string& msg) const;

  syslog::LogSeverity min_severity_;
  zx_koid_t pid_;
  mutable fit::variant<zx::socket, std::ofstream> descriptor_ = zx::socket();
  std::string tags_[kMaxTags];
  std::string tag_str_;
  size_t num_tags_ = 0;
};

void BeginRecord(LogBuffer* buffer, syslog::LogSeverity severity, const char* file_name,
                 unsigned int line, const char* msg, const char* condition) {
  // Ensure we have log state
  LogState::Get();
  zx_time_t time = zx_clock_get_monotonic();
  auto* state = RecordState::CreatePtr(buffer);
  RecordState& record = *state;
  new (state) RecordState;
  state->log_severity = severity;
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  encoder.Begin(*state, time, ::fuchsia::diagnostics::Severity(severity));
  encoder.AppendArgumentKey(record, SliceFromArray(kPidFieldName));
  encoder.AppendArgumentValue(record, static_cast<uint64_t>(pid));
  encoder.AppendArgumentKey(record, SliceFromArray(kTidFieldName));
  encoder.AppendArgumentValue(record, static_cast<uint64_t>(tid));

  auto dropped_count = GetAndResetDropped();
  record.dropped_count = dropped_count;
  if (dropped_count) {
    encoder.AppendArgumentKey(record, SliceFromString(kDroppedLogsFieldName));
    encoder.AppendArgumentValue(record, static_cast<uint64_t>(dropped_count));
  }
  for (size_t i = 0; i < GetState()->tag_count(); i++) {
    encoder.AppendArgumentKey(record, SliceFromString(kTagFieldName));
    encoder.AppendArgumentValue(record, SliceFromString(GetState()->tags()[i]));
  }
  if (msg) {
    encoder.AppendArgumentKey(record, SliceFromString(kMessageFieldName));
    encoder.AppendArgumentValue(record, SliceFromString(msg));
  }

  // TODO(fxbug.dev/56051): Enable this everywhere once doing so won't spam everything.
  if (severity >= syslog::LOG_ERROR) {
    encoder.AppendArgumentKey(record, SliceFromString(kFileFieldName));
    encoder.AppendArgumentValue(record, SliceFromString(file_name));

    encoder.AppendArgumentKey(record, SliceFromString(kLineFieldName));
    encoder.AppendArgumentValue(record, static_cast<uint64_t>(line));
  }
}

void WriteKeyValue(LogBuffer* buffer, const char* key, const char* value) {
  auto* state = RecordState::CreatePtr(buffer);
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  encoder.AppendArgumentKey(*state, DataSlice<const char>(key, strlen(key)));
  encoder.AppendArgumentValue(*state, DataSlice<const char>(value, strlen(value)));
}

void WriteKeyValue(LogBuffer* buffer, const char* key, int64_t value) {
  auto* state = RecordState::CreatePtr(buffer);
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  encoder.AppendArgumentKey(*state, DataSlice<const char>(key, strlen(key)));
  encoder.AppendArgumentValue(*state, value);
}

void WriteKeyValue(LogBuffer* buffer, const char* key, uint64_t value) {
  auto* state = RecordState::CreatePtr(buffer);
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  encoder.AppendArgumentKey(*state, DataSlice<const char>(key, strlen(key)));
  encoder.AppendArgumentValue(*state, value);
}

void WriteKeyValue(LogBuffer* buffer, const char* key, double value) {
  auto* state = RecordState::CreatePtr(buffer);
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  encoder.AppendArgumentKey(*state, DataSlice<const char>(key, strlen(key)));
  encoder.AppendArgumentValue(*state, value);
}

void EndRecord(LogBuffer* buffer) {
  auto* state = RecordState::CreatePtr(buffer);
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  encoder.End(*state);
}

bool FlushRecord(LogBuffer* buffer) {
  auto* state = RecordState::CreatePtr(buffer);
  if (!state->encode_success) {
    return false;
  }
  ExternalDataBuffer external_buffer(buffer);
  Encoder<ExternalDataBuffer> encoder(external_buffer);
  auto slice = external_buffer.GetSlice();

  auto& socket = fit::get<zx::socket>(GetState()->descriptor());
  auto status = socket.write(0, slice.data(), slice.size() * sizeof(log_word_t), nullptr);
  if (status != ZX_OK) {
    AddDropped(state->dropped_count + 1);
  }
  return status != ZX_ERR_BAD_STATE && status != ZX_ERR_PEER_CLOSED &&
         state->log_severity != syslog::LOG_FATAL;
}

bool LogState::WriteLogToFile(std::ofstream* file_ptr, zx_time_t time, zx_koid_t pid, zx_koid_t tid,
                              syslog::LogSeverity severity, const char* file_name,
                              unsigned int line, const char* tag, const char* condition,
                              const std::string& msg) const {
  auto& file = *file_ptr;
  file << "[" << std::setw(5) << std::setfill('0') << time / 1000000000UL << "." << std::setw(6)
       << (time / 1000UL) % 1000000UL << std::setw(0) << "][" << pid << "][" << tid << "][";

  auto& tag_str = tag_str_;
  file << tag_str;

  if (tag) {
    if (!tag_str.empty()) {
      file << ", ";
    }

    file << tag;
  }

  file << "] ";

  switch (severity) {
    case syslog::LOG_TRACE:
      file << "TRACE";
      break;
    case syslog::LOG_DEBUG:
      file << "DEBUG";
      break;
    case syslog::LOG_INFO:
      file << "INFO";
      break;
    case syslog::LOG_WARNING:
      file << "WARNING";
      break;
    case syslog::LOG_ERROR:
      file << "ERROR";
      break;
    case syslog::LOG_FATAL:
      file << "FATAL";
      break;
    default:
      file << "VLOG(" << (syslog::LOG_INFO - severity) << ")";
  }

  file << ": [" << file_name << "(" << line << ")] " << msg << std::endl;

  return severity != syslog::LOG_FATAL;
}

const LogState& LogState::Get() {
  auto state = GetState();

  if (!state) {
    Set(syslog::LogSettings());
    state = GetState();
  }

  return *state;
}

void LogState::Set(const syslog::LogSettings& settings) { Set(settings, {}); }

void LogState::Set(const syslog::LogSettings& settings,
                   const std::initializer_list<std::string>& tags) {
  if (auto old = SetState(new LogState(settings, tags))) {
    delete old;
  }
}

LogState::LogState(const syslog::LogSettings& settings,
                   const std::initializer_list<std::string>& tags)
    : min_severity_(settings.min_log_level), pid_(pid) {
  min_severity_ = settings.min_log_level;

  std::ostringstream tag_str;

  for (auto& tag : tags) {
    if (num_tags_) {
      tag_str << ", ";
    }
    tag_str << tag;
    tags_[num_tags_++] = tag;
    if (num_tags_ >= kMaxTags)
      break;
  }

  tag_str_ = tag_str.str();

  std::ofstream file;
  if (!settings.log_file.empty()) {
    file.open(settings.log_file, std::ios::out | std::ios::app);
  }

  if (file.is_open()) {
    descriptor_ = std::move(file);
  } else {
    zx::channel logger, logger_request;
    if (zx::channel::create(0, &logger, &logger_request) != ZX_OK) {
      return;
    }
    ::fuchsia::logger::LogSink_SyncProxy logger_client(std::move(logger));
    if (fdio_service_connect("/svc/fuchsia.logger.LogSink", logger_request.release()) != ZX_OK) {
      return;
    }
    zx::socket local, remote;
    if (zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote) != ZX_OK) {
      return;
    }

    auto result = logger_client.ConnectStructured(std::move(remote));
    if (result != ZX_OK) {
      return;
    }

    descriptor_ = std::move(local);
  }
}

template <typename T>
void LogState::WriteLog(syslog::LogSeverity severity, const char* file_name, unsigned int line,
                        const char* msg, const char* condition, const T& value) const {
  zx_time_t time = zx_clock_get_monotonic();

  // Cached getter for a stringified version of the log message, so we stringify at most once.
  auto msg_str = [as_str = std::string(), condition, msg, &value]() mutable -> const std::string& {
    if (as_str.empty()) {
      as_str = FullMessageString(condition, msg, value);
    }

    return as_str;
  };

  if (fit::holds_alternative<std::ofstream>(descriptor_)) {
    auto& file = fit::get<std::ofstream>(descriptor_);
    if (WriteLogToFile(&file, time, pid_, tid, severity, file_name, line, nullptr, condition,
                       msg_str())) {
      return;
    }
  } else if (fit::holds_alternative<zx::socket>(descriptor_)) {
    auto& socket = fit::get<zx::socket>(descriptor_);
    std::string message;
    if (msg) {
      message.assign(msg);
    }
    if (WriteLogToSocket(&socket, time, pid_, tid, severity, file_name, line, message, condition,
                         value)) {
      return;
    }
  }

  std::cerr << msg_str() << std::endl;
}

void SetLogSettings(const syslog::LogSettings& settings) { LogState::Set(settings); }

void SetLogSettings(const syslog::LogSettings& settings,
                    const std::initializer_list<std::string>& tags) {
  LogState::Set(settings, tags);
}

syslog::LogSeverity GetMinLogLevel() { return LogState::Get().min_severity(); }

}  // namespace syslog_backend