nghttp2/src/shrpx_log.cc

/*
 * nghttp2 - HTTP/2 C Library
 *
 * Copyright (c) 2012 Tatsuhiro Tsujikawa
 *
 * Permission is hereby granted, free of charge, to any person obtaining
 * a copy of this software and associated documentation files (the
 * "Software"), to deal in the Software without restriction, including
 * without limitation the rights to use, copy, modify, merge, publish,
 * distribute, sublicense, and/or sell copies of the Software, and to
 * permit persons to whom the Software is furnished to do so, subject to
 * the following conditions:
 *
 * The above copyright notice and this permission notice shall be
 * included in all copies or substantial portions of the Software.
 *
 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
 * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
 * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
 * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
 * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
 * OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
 * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
 */
#include "shrpx_log.h"

#ifdef HAVE_SYSLOG_H
#include <syslog.h>
#endif // HAVE_SYSLOG_H
#ifdef HAVE_UNISTD_H
#include <unistd.h>
#endif // HAVE_UNISTD_H
#ifdef HAVE_INTTYPES_H
#include <inttypes.h>
#endif // HAVE_INTTYPES_H
#include <sys/types.h>
#include <sys/stat.h>
#ifdef HAVE_FCNTL_H
#include <fcntl.h>
#endif // HAVE_FCNTL_H
#include <sys/wait.h>

#include <cerrno>
#include <cstdio>
#include <cstring>
#include <ctime>
#include <iostream>
#include <iomanip>

#include "shrpx_config.h"
#include "shrpx_downstream.h"
#include "shrpx_worker.h"
#include "util.h"
#include "template.h"

using namespace nghttp2;

namespace shrpx {

namespace {
const StringRef SEVERITY_STR[] = {
    StringRef::from_lit("INFO"), StringRef::from_lit("NOTICE"),
    StringRef::from_lit("WARN"), StringRef::from_lit("ERROR"),
    StringRef::from_lit("FATAL")};
} // namespace

namespace {
const char *SEVERITY_COLOR[] = {
    "\033[1;32m", // INFO
    "\033[1;36m", // NOTICE
    "\033[1;33m", // WARN
    "\033[1;31m", // ERROR
    "\033[1;35m", // FATAL
};
} // namespace

int Log::severity_thres_ = NOTICE;

void Log::set_severity_level(int severity) { severity_thres_ = severity; }

int Log::set_severity_level_by_name(const StringRef &name) {
  for (size_t i = 0, max = array_size(SEVERITY_STR); i < max; ++i) {
    if (name == SEVERITY_STR[i]) {
      severity_thres_ = i;
      return 0;
    }
  }
  return -1;
}

int severity_to_syslog_level(int severity) {
  switch (severity) {
  case (INFO):
    return LOG_INFO;
  case (NOTICE):
    return LOG_NOTICE;
  case (WARN):
    return LOG_WARNING;
  case (ERROR):
    return LOG_ERR;
  case (FATAL):
    return LOG_CRIT;
  default:
    return -1;
  }
}

Log::Log(int severity, const char *filename, int linenum)
    : filename_(filename), severity_(severity), linenum_(linenum) {}

Log::~Log() {
  int rv;
  auto config = get_config();

  if (!config) {
    return;
  }

  auto lgconf = log_config();

  auto &errorconf = config->logging.error;

  if (!log_enabled(severity_) ||
      (lgconf->errorlog_fd == -1 && !errorconf.syslog)) {
    return;
  }

  if (errorconf.syslog) {
    if (severity_ == NOTICE) {
      syslog(severity_to_syslog_level(severity_), "[%s] %s",
             SEVERITY_STR[severity_].c_str(), stream_.str().c_str());
    } else {
      syslog(severity_to_syslog_level(severity_), "[%s] %s (%s:%d)",
             SEVERITY_STR[severity_].c_str(), stream_.str().c_str(), filename_,
             linenum_);
    }

    return;
  }

  char buf[4_k];
  auto tty = lgconf->errorlog_tty;

  lgconf->update_tstamp(std::chrono::system_clock::now());

  // Error log format: <datetime> <master-pid> <current-pid>
  // <thread-id> <level> (<filename>:<line>) <msg>
  rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %s\n",
                lgconf->time_iso8601.c_str(), config->pid, lgconf->pid,
                lgconf->thread_id.c_str(), tty ? SEVERITY_COLOR[severity_] : "",
                SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
                filename_, linenum_, stream_.str().c_str());

  if (rv < 0) {
    return;
  }

  auto nwrite = std::min(static_cast<size_t>(rv), sizeof(buf) - 1);

  while (write(lgconf->errorlog_fd, buf, nwrite) == -1 && errno == EINTR)
    ;
}

namespace {
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy(const char *src, size_t srclen,
                                       size_t avail, OutputIterator oitr) {
  auto nwrite = std::min(srclen, avail);
  auto noitr = std::copy_n(src, nwrite, oitr);
  return std::make_pair(noitr, avail - nwrite);
}
} // namespace

namespace {
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy(const char *src, size_t avail,
                                       OutputIterator oitr) {
  return copy(src, strlen(src), avail, oitr);
}
} // namespace

namespace {
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy(const std::string &src, size_t avail,
                                       OutputIterator oitr) {
  return copy(src.c_str(), src.size(), avail, oitr);
}
} // namespace

namespace {
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy(const StringRef &src, size_t avail,
                                       OutputIterator oitr) {
  return copy(src.c_str(), src.size(), avail, oitr);
}
} // namespace

namespace {
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy(const ImmutableString &src, size_t avail,
                                       OutputIterator oitr) {
  return copy(src.c_str(), src.size(), avail, oitr);
}
} // namespace

namespace {
template <size_t N, typename OutputIterator>
std::pair<OutputIterator, size_t> copy_l(const char (&src)[N], size_t avail,
                                         OutputIterator oitr) {
  return copy(src, N - 1, avail, oitr);
}
} // namespace

namespace {
const char LOWER_XDIGITS[] = "0123456789abcdef";
} // namespace

namespace {
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy_hex_low(const uint8_t *src,
                                               size_t srclen, size_t avail,
                                               OutputIterator oitr) {
  auto nwrite = std::min(srclen * 2, avail) / 2;
  for (auto i = 0u; i < nwrite; ++i) {
    *oitr++ = LOWER_XDIGITS[src[i] >> 4];
    *oitr++ = LOWER_XDIGITS[src[i] & 0xf];
  }
  return std::make_pair(oitr, avail - nwrite);
}
} // namespace

void upstream_accesslog(const std::vector<LogFragment> &lfv,
                        const LogSpec &lgsp) {
  auto lgconf = log_config();
  auto &accessconf = get_config()->logging.access;

  if (lgconf->accesslog_fd == -1 && !accessconf.syslog) {
    return;
  }

  char buf[4_k];

  auto downstream = lgsp.downstream;

  const Request *req = nullptr;
  if (downstream) {
    req = &downstream->request();
  }

  auto p = buf;
  auto avail = sizeof(buf) - 2;

  lgconf->update_tstamp(lgsp.time_now);
  auto &time_local = lgconf->time_local;
  auto &time_iso8601 = lgconf->time_iso8601;

  for (auto &lf : lfv) {
    switch (lf.type) {
    case SHRPX_LOGF_LITERAL:
      std::tie(p, avail) = copy(lf.value, avail, p);
      break;
    case SHRPX_LOGF_REMOTE_ADDR:
      std::tie(p, avail) = copy(lgsp.remote_addr, avail, p);
      break;
    case SHRPX_LOGF_TIME_LOCAL:
      std::tie(p, avail) = copy(time_local, avail, p);
      break;
    case SHRPX_LOGF_TIME_ISO8601:
      std::tie(p, avail) = copy(time_iso8601, avail, p);
      break;
    case SHRPX_LOGF_REQUEST:
      std::tie(p, avail) = copy(lgsp.method, avail, p);
      std::tie(p, avail) = copy_l(" ", avail, p);
      std::tie(p, avail) = copy(lgsp.path, avail, p);
      std::tie(p, avail) = copy_l(" HTTP/", avail, p);
      std::tie(p, avail) = copy(util::utos(lgsp.major), avail, p);
      if (lgsp.major < 2) {
        std::tie(p, avail) = copy_l(".", avail, p);
        std::tie(p, avail) = copy(util::utos(lgsp.minor), avail, p);
      }
      break;
    case SHRPX_LOGF_STATUS:
      std::tie(p, avail) = copy(util::utos(lgsp.status), avail, p);
      break;
    case SHRPX_LOGF_BODY_BYTES_SENT:
      std::tie(p, avail) = copy(util::utos(lgsp.body_bytes_sent), avail, p);
      break;
    case SHRPX_LOGF_HTTP:
      if (req) {
        auto hd = req->fs.header(lf.value);
        if (hd) {
          std::tie(p, avail) = copy((*hd).value, avail, p);
          break;
        }
      }

      std::tie(p, avail) = copy_l("-", avail, p);

      break;
    case SHRPX_LOGF_AUTHORITY:
      if (req) {
        if (!req->authority.empty()) {
          std::tie(p, avail) = copy(req->authority, avail, p);
          break;
        }
      }

      std::tie(p, avail) = copy_l("-", avail, p);

      break;
    case SHRPX_LOGF_REMOTE_PORT:
      std::tie(p, avail) = copy(lgsp.remote_port, avail, p);
      break;
    case SHRPX_LOGF_SERVER_PORT:
      std::tie(p, avail) = copy(util::utos(lgsp.server_port), avail, p);
      break;
    case SHRPX_LOGF_REQUEST_TIME: {
      auto t = std::chrono::duration_cast<std::chrono::milliseconds>(
                   lgsp.request_end_time - lgsp.request_start_time)
                   .count();

      auto frac = util::utos(t % 1000);
      auto sec = util::utos(t / 1000);
      if (frac.size() < 3) {
        frac = std::string(3 - frac.size(), '0') + frac;
      }
      sec += '.';
      sec += frac;

      std::tie(p, avail) = copy(sec, avail, p);
    } break;
    case SHRPX_LOGF_PID:
      std::tie(p, avail) = copy(util::utos(lgsp.pid), avail, p);
      break;
    case SHRPX_LOGF_ALPN:
      std::tie(p, avail) = copy(lgsp.alpn, avail, p);
      break;
    case SHRPX_LOGF_SSL_CIPHER:
      if (!lgsp.tls_info) {
        std::tie(p, avail) = copy_l("-", avail, p);
        break;
      }
      std::tie(p, avail) = copy(lgsp.tls_info->cipher, avail, p);
      break;
    case SHRPX_LOGF_SSL_PROTOCOL:
      if (!lgsp.tls_info) {
        std::tie(p, avail) = copy_l("-", avail, p);
        break;
      }
      std::tie(p, avail) = copy(lgsp.tls_info->protocol, avail, p);
      break;
    case SHRPX_LOGF_SSL_SESSION_ID:
      if (!lgsp.tls_info || lgsp.tls_info->session_id_length == 0) {
        std::tie(p, avail) = copy_l("-", avail, p);
        break;
      }
      std::tie(p, avail) =
          copy_hex_low(lgsp.tls_info->session_id,
                       lgsp.tls_info->session_id_length, avail, p);
      break;
    case SHRPX_LOGF_SSL_SESSION_REUSED:
      if (!lgsp.tls_info) {
        std::tie(p, avail) = copy_l("-", avail, p);
        break;
      }
      std::tie(p, avail) =
          copy_l(lgsp.tls_info->session_reused ? "r" : ".", avail, p);
      break;
    case SHRPX_LOGF_BACKEND_HOST:
      if (!lgsp.downstream_addr) {
        std::tie(p, avail) = copy_l("-", avail, p);
        break;
      }
      std::tie(p, avail) = copy(lgsp.downstream_addr->host, avail, p);
      break;
    case SHRPX_LOGF_BACKEND_PORT:
      if (!lgsp.downstream_addr) {
        std::tie(p, avail) = copy_l("-", avail, p);
        break;
      }
      std::tie(p, avail) =
          copy(util::utos(lgsp.downstream_addr->port), avail, p);
      break;
    case SHRPX_LOGF_NONE:
      break;
    default:
      break;
    }
  }

  *p = '\0';

  if (accessconf.syslog) {
    syslog(LOG_INFO, "%s", buf);

    return;
  }

  *p++ = '\n';

  auto nwrite = p - buf;
  while (write(lgconf->accesslog_fd, buf, nwrite) == -1 && errno == EINTR)
    ;
}

int reopen_log_files() {
  int res = 0;
  int new_accesslog_fd = -1;
  int new_errorlog_fd = -1;

  auto lgconf = log_config();
  auto config = get_config();
  auto &accessconf = config->logging.access;
  auto &errorconf = config->logging.error;

  if (!accessconf.syslog && !accessconf.file.empty()) {
    new_accesslog_fd = open_log_file(accessconf.file.c_str());

    if (new_accesslog_fd == -1) {
      LOG(ERROR) << "Failed to open accesslog file " << accessconf.file;
      res = -1;
    }
  }

  if (!errorconf.syslog && !errorconf.file.empty()) {
    new_errorlog_fd = open_log_file(errorconf.file.c_str());

    if (new_errorlog_fd == -1) {
      if (lgconf->errorlog_fd != -1) {
        LOG(ERROR) << "Failed to open errorlog file " << errorconf.file;
      } else {
        std::cerr << "Failed to open errorlog file " << errorconf.file
                  << std::endl;
      }

      res = -1;
    }
  }

  close_log_file(lgconf->accesslog_fd);
  close_log_file(lgconf->errorlog_fd);

  lgconf->accesslog_fd = new_accesslog_fd;
  lgconf->errorlog_fd = new_errorlog_fd;
  lgconf->errorlog_tty =
      (new_errorlog_fd == -1) ? false : isatty(new_errorlog_fd);

  return res;
}

void log_chld(pid_t pid, int rstatus, const char *msg) {
  std::string signalstr;
  if (WIFSIGNALED(rstatus)) {
    signalstr += "; signal ";
    auto sig = WTERMSIG(rstatus);
    auto s = strsignal(sig);
    if (s) {
      signalstr += s;
      signalstr += '(';
    } else {
      signalstr += "UNKNOWN(";
    }
    signalstr += util::utos(sig);
    signalstr += ')';
  }

  LOG(NOTICE) << msg << ": [" << pid << "] exited "
              << (WIFEXITED(rstatus) ? "normally" : "abnormally")
              << " with status " << std::hex << rstatus << std::oct
              << "; exit status " << WEXITSTATUS(rstatus)
              << (signalstr.empty() ? "" : signalstr.c_str());
}

void redirect_stderr_to_errorlog() {
  auto lgconf = log_config();
  auto &errorconf = get_config()->logging.error;

  if (errorconf.syslog || lgconf->errorlog_fd == -1) {
    return;
  }

  dup2(lgconf->errorlog_fd, STDERR_FILENO);
}

namespace {
int STDERR_COPY = -1;
int STDOUT_COPY = -1;
} // namespace

void store_original_fds() {
  // consider dup'ing stdout too
  STDERR_COPY = dup(STDERR_FILENO);
  STDOUT_COPY = STDOUT_FILENO;
  // no race here, since it is called early
  util::make_socket_closeonexec(STDERR_COPY);
}

void restore_original_fds() { dup2(STDERR_COPY, STDERR_FILENO); }

void close_log_file(int &fd) {
  if (fd != STDERR_COPY && fd != STDOUT_COPY && fd != -1) {
    close(fd);
  }
  fd = -1;
}

int open_log_file(const char *path) {

  if (strcmp(path, "/dev/stdout") == 0 ||
      strcmp(path, "/proc/self/fd/1") == 0) {
    return STDOUT_COPY;
  }

  if (strcmp(path, "/dev/stderr") == 0 ||
      strcmp(path, "/proc/self/fd/2") == 0) {
    return STDERR_COPY;
  }
#if defined O_CLOEXEC

  auto fd = open(path, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC,
                 S_IRUSR | S_IWUSR | S_IRGRP);
#else // !O_CLOEXEC

  auto fd =
      open(path, O_WRONLY | O_APPEND | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP);

  // We get race condition if execve is called at the same time.
  if (fd != -1) {
    util::make_socket_closeonexec(fd);
  }

#endif // !O_CLOEXEC

  if (fd == -1) {
    return -1;
  }

  return fd;
}

} // namespace shrpx