nghttp2/src/shrpx_log.cc

407 lines
11 KiB
C++
Raw Normal View History

/*
2014-03-30 12:09:21 +02:00
* 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"
2015-05-13 15:30:35 +02:00
#ifdef HAVE_SYSLOG_H
2012-08-01 18:20:18 +02:00
#include <syslog.h>
2015-05-13 15:30:35 +02:00
#endif // HAVE_SYSLOG_H
#ifdef HAVE_UNISTD_H
#include <unistd.h>
2015-05-13 15:30:35 +02:00
#endif // HAVE_UNISTD_H
#ifdef HAVE_INTTYPES_H
#include <inttypes.h>
2015-05-13 15:30:35 +02:00
#endif // HAVE_INTTYPES_H
2012-08-01 18:20:18 +02:00
2014-08-05 17:23:46 +02:00
#include <cerrno>
#include <cstdio>
2012-06-06 16:58:19 +02:00
#include <cstring>
#include <ctime>
#include <iostream>
#include <iomanip>
2012-08-01 18:20:18 +02:00
#include "shrpx_config.h"
#include "shrpx_downstream.h"
#include "util.h"
#include "template.h"
using namespace nghttp2;
2012-08-01 18:20:18 +02:00
namespace shrpx {
namespace {
2014-11-27 15:39:04 +01:00
const char *SEVERITY_STR[] = {"INFO", "NOTICE", "WARN", "ERROR", "FATAL"};
} // namespace
namespace {
const char *SEVERITY_COLOR[] = {
2014-11-27 15:39:04 +01:00
"\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;
2014-11-27 15:39:04 +01:00
void Log::set_severity_level(int severity) { severity_thres_ = severity; }
2014-11-27 15:39:04 +01:00
int Log::set_severity_level_by_name(const char *name) {
for (size_t i = 0, max = array_size(SEVERITY_STR); i < max; ++i) {
2014-11-27 15:39:04 +01:00
if (strcmp(SEVERITY_STR[i], name) == 0) {
2012-06-06 16:58:19 +02:00
severity_thres_ = i;
return 0;
}
}
return -1;
}
2014-11-27 15:39:04 +01:00
int severity_to_syslog_level(int severity) {
switch (severity) {
case (INFO):
2012-08-01 18:20:18 +02:00
return LOG_INFO;
2014-11-27 15:39:04 +01:00
case (NOTICE):
return LOG_NOTICE;
2014-11-27 15:39:04 +01:00
case (WARN):
2012-08-01 18:20:18 +02:00
return LOG_WARNING;
2014-11-27 15:39:04 +01:00
case (ERROR):
2012-08-01 18:20:18 +02:00
return LOG_ERR;
2014-11-27 15:39:04 +01:00
case (FATAL):
2012-08-01 18:20:18 +02:00
return LOG_CRIT;
default:
2012-08-01 19:07:51 +02:00
return -1;
2012-08-01 18:20:18 +02:00
}
}
Log::Log(int severity, const char *filename, int linenum)
2014-11-27 15:39:04 +01:00
: filename_(filename), severity_(severity), linenum_(linenum) {}
2014-11-27 15:39:04 +01:00
Log::~Log() {
int rv;
2014-11-27 15:39:04 +01:00
if (!get_config()) {
return;
}
auto lgconf = log_config();
2014-08-19 14:33:54 +02:00
2014-11-27 15:39:04 +01:00
if (!log_enabled(severity_) ||
(lgconf->errorlog_fd == -1 && !get_config()->errorlog_syslog)) {
return;
}
2014-11-27 15:39:04 +01:00
if (get_config()->errorlog_syslog) {
if (severity_ == NOTICE) {
syslog(severity_to_syslog_level(severity_), "[%s] %s",
SEVERITY_STR[severity_], stream_.str().c_str());
} else {
syslog(severity_to_syslog_level(severity_), "[%s] %s (%s:%d)",
2014-11-27 15:39:04 +01:00
SEVERITY_STR[severity_], stream_.str().c_str(), filename_,
linenum_);
}
return;
}
char buf[4_k];
auto tty = lgconf->errorlog_tty;
lgconf->update_tstamp(std::chrono::system_clock::now());
auto &time_local = lgconf->time_local_str;
if (severity_ == NOTICE) {
rv = snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s\n",
time_local.c_str(), get_config()->pid,
tty ? SEVERITY_COLOR[severity_] : "", SEVERITY_STR[severity_],
tty ? "\033[0m" : "", stream_.str().c_str());
} else {
2014-11-27 15:39:04 +01:00
rv = snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s%s:%d%s %s\n",
time_local.c_str(), get_config()->pid,
2014-11-27 15:39:04 +01:00
tty ? SEVERITY_COLOR[severity_] : "", SEVERITY_STR[severity_],
tty ? "\033[0m" : "", tty ? "\033[1;30m" : "", filename_,
linenum_, tty ? "\033[0m" : "", stream_.str().c_str());
}
2014-11-27 15:39:04 +01:00
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)
2014-11-27 15:39:04 +01:00
;
}
namespace {
2014-11-27 15:39:04 +01:00
template <typename OutputIterator>
std::pair<OutputIterator, size_t> copy(const char *src, size_t avail,
OutputIterator oitr) {
auto nwrite = std::min(strlen(src), avail);
auto noitr = std::copy_n(src, nwrite, oitr);
return std::make_pair(noitr, avail - nwrite);
}
} // 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;
2015-06-30 14:33:54 +02:00
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();
2014-08-19 14:33:54 +02:00
if (lgconf->accesslog_fd == -1 && !get_config()->accesslog_syslog) {
return;
}
char buf[4_k];
auto downstream = lgsp.downstream;
auto p = buf;
auto avail = sizeof(buf) - 2;
lgconf->update_tstamp(lgsp.time_now);
auto &time_local = lgconf->time_local_str;
auto &time_iso8601 = lgconf->time_iso8601_str;
2014-11-27 15:39:04 +01:00
for (auto &lf : lfv) {
switch (lf.type) {
case SHRPX_LOGF_LITERAL:
std::tie(p, avail) = copy(lf.value.get(), 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.c_str(), avail, p);
break;
case SHRPX_LOGF_TIME_ISO8601:
std::tie(p, avail) = copy(time_iso8601.c_str(), avail, p);
break;
case SHRPX_LOGF_REQUEST:
std::tie(p, avail) = copy(lgsp.method, avail, p);
std::tie(p, avail) = copy(" ", avail, p);
std::tie(p, avail) = copy(lgsp.path, avail, p);
std::tie(p, avail) = copy(" HTTP/", avail, p);
std::tie(p, avail) = copy(util::utos(lgsp.major).c_str(), avail, p);
if (lgsp.major < 2) {
std::tie(p, avail) = copy(".", avail, p);
std::tie(p, avail) = copy(util::utos(lgsp.minor).c_str(), avail, p);
}
break;
case SHRPX_LOGF_STATUS:
std::tie(p, avail) = copy(util::utos(lgsp.status).c_str(), avail, p);
break;
case SHRPX_LOGF_BODY_BYTES_SENT:
2014-11-27 15:39:04 +01:00
std::tie(p, avail) =
copy(util::utos(lgsp.body_bytes_sent).c_str(), avail, p);
break;
case SHRPX_LOGF_HTTP:
2014-11-27 15:39:04 +01:00
if (downstream) {
auto hd = downstream->get_request_header(lf.value.get());
if (hd) {
std::tie(p, avail) = copy((*hd).value.c_str(), avail, p);
break;
}
}
std::tie(p, avail) = copy("-", 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).c_str(), avail, p);
break;
2014-11-27 15:39:04 +01:00
case SHRPX_LOGF_REQUEST_TIME: {
auto t = std::chrono::duration_cast<std::chrono::milliseconds>(
lgsp.request_end_time - lgsp.request_start_time).count();
2014-11-27 15:39:04 +01:00
auto frac = util::utos(t % 1000);
auto sec = util::utos(t / 1000);
if (frac.size() < 3) {
frac = std::string(3 - frac.size(), '0') + frac;
}
2014-11-27 15:39:04 +01:00
sec += ".";
sec += frac;
std::tie(p, avail) = copy(sec.c_str(), avail, p);
} break;
case SHRPX_LOGF_PID:
std::tie(p, avail) = copy(util::utos(lgsp.pid).c_str(), 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("-", 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("-", 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("-", 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("-", avail, p);
break;
}
std::tie(p, avail) =
copy(lgsp.tls_info->session_reused ? "r" : ".", avail, p);
break;
case SHRPX_LOGF_NONE:
break;
default:
break;
}
}
*p = '\0';
2014-11-27 15:39:04 +01:00
if (get_config()->accesslog_syslog) {
syslog(LOG_INFO, "%s", buf);
return;
}
*p++ = '\n';
auto nwrite = p - buf;
while (write(lgconf->accesslog_fd, buf, nwrite) == -1 && errno == EINTR)
2014-11-27 15:39:04 +01:00
;
}
2014-11-27 15:39:04 +01:00
int reopen_log_files() {
int res = 0;
int new_accesslog_fd = -1;
int new_errorlog_fd = -1;
auto lgconf = log_config();
2014-08-19 14:33:54 +02:00
2014-11-27 15:39:04 +01:00
if (!get_config()->accesslog_syslog && get_config()->accesslog_file) {
new_accesslog_fd = util::open_log_file(get_config()->accesslog_file.get());
if (new_accesslog_fd == -1) {
LOG(ERROR) << "Failed to open accesslog file "
<< get_config()->accesslog_file.get();
res = -1;
}
}
2014-11-27 15:39:04 +01:00
if (!get_config()->errorlog_syslog && get_config()->errorlog_file) {
new_errorlog_fd = util::open_log_file(get_config()->errorlog_file.get());
2014-11-27 15:39:04 +01:00
if (new_errorlog_fd == -1) {
if (lgconf->errorlog_fd != -1) {
LOG(ERROR) << "Failed to open errorlog file "
<< get_config()->errorlog_file.get();
} else {
std::cerr << "Failed to open errorlog file "
2014-11-27 15:39:04 +01:00
<< get_config()->errorlog_file.get() << std::endl;
}
res = -1;
}
}
util::close_log_file(lgconf->accesslog_fd);
util::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();
if (get_config()->errorlog_syslog || lgconf->errorlog_fd == -1) {
return;
}
dup2(lgconf->errorlog_fd, STDERR_FILENO);
}
} // namespace shrpx