From 9c824b87fe647c4d587fe365d9bd63704ec826fe Mon Sep 17 00:00:00 2001 From: Tatsuhiro Tsujikawa Date: Fri, 31 Aug 2018 21:55:33 +0900 Subject: [PATCH] nghttpx: Get rid of std::stringstream from Log --- src/shrpx_connection_handler.cc | 4 +- src/shrpx_log.cc | 218 ++++++++++++++++++++++++++++++-- src/shrpx_log.h | 102 ++++++++++++++- src/shrpx_tls.cc | 4 +- 4 files changed, 310 insertions(+), 18 deletions(-) diff --git a/src/shrpx_connection_handler.cc b/src/shrpx_connection_handler.cc index 0f69c098..05bbc3a8 100644 --- a/src/shrpx_connection_handler.cc +++ b/src/shrpx_connection_handler.cc @@ -613,8 +613,8 @@ void ConnectionHandler::handle_ocsp_complete() { auto status = WEXITSTATUS(rstatus); if (ocsp_.error || !WIFEXITED(rstatus) || status != 0) { LOG(WARN) << "ocsp query command for " << tls_ctx_data->cert_file - << " failed: error=" << ocsp_.error << ", rstatus=" << std::hex - << rstatus << std::dec << ", status=" << status; + << " failed: error=" << ocsp_.error << ", rstatus=" << log::hex + << rstatus << log::dec << ", status=" << status; ++ocsp_.next; proceed_next_cert_ocsp(); return; diff --git a/src/shrpx_log.cc b/src/shrpx_log.cc index 0fafc6c2..8459d15e 100644 --- a/src/shrpx_log.cc +++ b/src/shrpx_log.cc @@ -74,6 +74,44 @@ constexpr const char *SEVERITY_COLOR[] = { }; } // namespace +#ifndef NOTHREADS +# ifdef HAVE_THREAD_LOCAL +namespace { +thread_local LogBuffer logbuf_; +} // namespace + +namespace { +LogBuffer *get_logbuf() { return &logbuf_; } +} // namespace +# else // !HAVE_THREAD_LOCAL +namespace { +pthread_key_t lckey; +pthread_once_t lckey_once = PTHREAD_ONCE_INIT; +} // namespace + +namespace { +void make_key() { pthread_key_create(&lckey, NULL); } +} // namespace + +LogBuffer *get_logbuf() { + pthread_once(&lckey_once, make_key); + auto buf = static_cast(pthread_getspecific(lckey)); + if (!buf) { + buf = new LogBuffer(); + pthread_setspecific(lckey, buf); + } + return buf; +} +# endif // !HAVE_THREAD_LOCAL +#else // NOTHREADS +namespace { +LogBuffer *get_logbuf() { + static LogBuffer logbuf; + return &logbuf; +} +} // namespace +#endif // NOTHREADS + int Log::severity_thres_ = NOTICE; void Log::set_severity_level(int severity) { severity_thres_ = severity; } @@ -106,7 +144,15 @@ int severity_to_syslog_level(int severity) { } Log::Log(int severity, const char *filename, int linenum) - : filename_(filename), severity_(severity), linenum_(linenum) {} + : buf_(*get_logbuf()), + begin_(buf_.data()), + end_(begin_ + buf_.size()), + last_(begin_), + filename_(filename), + flags_(0), + severity_(severity), + linenum_(linenum), + full_(false) {} Log::~Log() { int rv; @@ -127,12 +173,13 @@ Log::~Log() { if (errorconf.syslog) { if (severity_ == NOTICE) { - syslog(severity_to_syslog_level(severity_), "[%s] %s", - SEVERITY_STR[severity_].c_str(), stream_.str().c_str()); + syslog(severity_to_syslog_level(severity_), "[%s] %.*s", + SEVERITY_STR[severity_].c_str(), static_cast(rleft()), + begin_); } else { - syslog(severity_to_syslog_level(severity_), "[%s] %s (%s:%d)", - SEVERITY_STR[severity_].c_str(), stream_.str().c_str(), filename_, - linenum_); + syslog(severity_to_syslog_level(severity_), "[%s] %.*s (%s:%d)", + SEVERITY_STR[severity_].c_str(), static_cast(rleft()), begin_, + filename_, linenum_); } return; @@ -145,11 +192,11 @@ Log::~Log() { // Error log format: // (:) - rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %s\n", + rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %.*s\n", lgconf->tstamp->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()); + filename_, linenum_, static_cast(rleft()), begin_); if (rv < 0) { return; @@ -161,6 +208,156 @@ Log::~Log() { ; } +Log &Log::operator<<(const std::string &s) { + write_seq(std::begin(s), std::end(s)); + return *this; +} + +Log &Log::operator<<(const StringRef &s) { + write_seq(std::begin(s), std::end(s)); + return *this; +} + +Log &Log::operator<<(const char *s) { + write_seq(s, s + strlen(s)); + return *this; +} + +Log &Log::operator<<(const ImmutableString &s) { + write_seq(std::begin(s), std::end(s)); + return *this; +} + +Log &Log::operator<<(int64_t n) { + if (n >= 0) { + return *this << static_cast(n); + } + + if (flags_ & fmt_hex) { + write_hex(n); + return *this; + } + + if (full_) { + return *this; + } + + n *= -1; + + size_t nlen = 0; + for (auto t = n; t; t /= 10, ++nlen) + ; + if (wleft() < 1 /* sign */ + nlen) { + full_ = true; + return *this; + } + *last_++ = '-'; + *last_ += nlen; + update_full(); + + auto p = last_ - 1; + for (; n; n /= 10) { + *p-- = (n % 10) + '0'; + } + return *this; +} + +Log &Log::operator<<(uint64_t n) { + if (flags_ & fmt_hex) { + write_hex(n); + return *this; + } + + if (full_) { + return *this; + } + + if (n == 0) { + *last_++ = '0'; + update_full(); + return *this; + } + size_t nlen = 0; + for (auto t = n; t; t /= 10, ++nlen) + ; + if (wleft() < nlen) { + full_ = true; + return *this; + } + + last_ += nlen; + update_full(); + + auto p = last_ - 1; + for (; n; n /= 10) { + *p-- = (n % 10) + '0'; + } + return *this; +} + +Log &Log::operator<<(double n) { + if (full_) { + return *this; + } + + auto left = wleft(); + auto rv = snprintf(reinterpret_cast(last_), left, "%.9f", n); + if (rv > static_cast(left)) { + full_ = true; + return *this; + } + + last_ += rv; + update_full(); + + return *this; +} + +Log &Log::operator<<(long double n) { + if (full_) { + return *this; + } + + auto left = wleft(); + auto rv = snprintf(reinterpret_cast(last_), left, "%.9Lf", n); + if (rv > static_cast(left)) { + full_ = true; + return *this; + } + + last_ += rv; + update_full(); + + return *this; +} + +Log &Log::operator<<(bool n) { + if (full_) { + return *this; + } + + *last_++ = n ? '1' : '0'; + update_full(); + + return *this; +} + +Log &Log::operator<<(const void *p) { + if (full_) { + return *this; + } + + write_hex(reinterpret_cast(p)); + + return *this; +} + +namespace log { +void hex(Log &log) { log.set_flags(Log::fmt_hex); }; + +void dec(Log &log) { log.set_flags(Log::fmt_dec); }; +} // namespace log + namespace { template std::pair copy(const char *src, size_t srclen, @@ -696,8 +893,9 @@ void log_chld(pid_t pid, int rstatus, const char *msg) { LOG(NOTICE) << msg << ": [" << pid << "] exited " << (WIFEXITED(rstatus) ? "normally" : "abnormally") - << " with status " << std::hex << rstatus << std::oct - << "; exit status " << WEXITSTATUS(rstatus) + << " with status " << log::hex << rstatus << log::dec + << "; exit status " + << (WIFEXITED(rstatus) ? WEXITSTATUS(rstatus) : 0) << (signalstr.empty() ? "" : signalstr.c_str()); } diff --git a/src/shrpx_log.h b/src/shrpx_log.h index ea77fbc5..1130b8da 100644 --- a/src/shrpx_log.h +++ b/src/shrpx_log.h @@ -29,7 +29,6 @@ #include -#include #include #include #include @@ -38,6 +37,7 @@ #include "shrpx_log_config.h" #include "tls.h" #include "template.h" +#include "util.h" using namespace nghttp2; @@ -90,26 +90,120 @@ struct DownstreamAddr; enum SeverityLevel { INFO, NOTICE, WARN, ERROR, FATAL }; +using LogBuffer = std::array; + class Log { public: Log(int severity, const char *filename, int linenum); ~Log(); - template Log &operator<<(Type s) { - stream_ << s; + Log &operator<<(const std::string &s); + Log &operator<<(const char *s); + Log &operator<<(const StringRef &s); + Log &operator<<(const ImmutableString &s); + Log &operator<<(int16_t n) { return *this << static_cast(n); } + Log &operator<<(int32_t n) { return *this << static_cast(n); } + Log &operator<<(int64_t n); + Log &operator<<(uint16_t n) { return *this << static_cast(n); } + Log &operator<<(uint32_t n) { return *this << static_cast(n); } + Log &operator<<(uint64_t n); + Log &operator<<(float n) { return *this << static_cast(n); } + Log &operator<<(double n); + Log &operator<<(long double n); + Log &operator<<(bool n); + Log &operator<<(const void *p); + template Log &operator<<(const std::shared_ptr &ptr) { + return *this << ptr.get(); + } + Log &operator<<(void (*func)(Log &log)) { + func(*this); return *this; } + template void write_seq(InputIt first, InputIt last) { + if (full_) { + return; + } + + auto d = std::distance(first, last); + auto n = std::min(wleft(), static_cast(d)); + last_ = std::copy(first, first + n, last_); + update_full(); + } + + template void write_hex(T n) { + if (full_) { + return; + } + + if (n == 0) { + if (wleft() < 4 /* for "0x00" */) { + full_ = true; + return; + } + *last_++ = '0'; + *last_++ = 'x'; + *last_++ = '0'; + *last_++ = '0'; + update_full(); + return; + } + + size_t nlen = 0; + for (auto t = n; t; t >>= 8, ++nlen) + ; + + nlen *= 2; + + if (wleft() < 2 /* for "0x" */ + nlen) { + full_ = true; + return; + } + + *last_++ = '0'; + *last_++ = 'x'; + + last_ += nlen; + update_full(); + + auto p = last_ - 1; + for (; n; n >>= 8) { + uint8_t b = n & 0xff; + *p-- = util::LOWER_XDIGITS[b & 0xf]; + *p-- = util::LOWER_XDIGITS[b >> 4]; + } + } static void set_severity_level(int severity); static int set_severity_level_by_name(const StringRef &name); static bool log_enabled(int severity) { return severity >= severity_thres_; } + enum { + fmt_dec = 0x00, + fmt_hex = 0x01, + }; + + void set_flags(int flags) { flags_ = flags; } + private: - std::stringstream stream_; + size_t rleft() { return last_ - begin_; } + size_t wleft() { return end_ - last_; } + void update_full() { full_ = last_ == end_; } + + LogBuffer &buf_; + uint8_t *begin_; + uint8_t *end_; + uint8_t *last_; const char *filename_; + uint32_t flags_; int severity_; int linenum_; + bool full_; static int severity_thres_; }; +namespace log { +void hex(Log &log); +void dec(Log &log); +} // namespace log + #define TTY_HTTP_HD (log_config()->errorlog_tty ? "\033[1;34m" : "") #define TTY_RST (log_config()->errorlog_tty ? "\033[0m" : "") diff --git a/src/shrpx_tls.cc b/src/shrpx_tls.cc index 0a834546..2fd61465 100644 --- a/src/shrpx_tls.cc +++ b/src/shrpx_tls.cc @@ -591,7 +591,7 @@ int sct_add_cb(SSL *ssl, unsigned int ext_type, unsigned int context, if (LOG_ENABLED(INFO)) { LOG(INFO) << "sct_add_cb is called, chainidx=" << chainidx << ", x=" << x - << ", context=" << std::hex << context; + << ", context=" << log::hex << context; } // We only have SCTs for leaf certificate. @@ -1856,7 +1856,7 @@ void try_cache_tls_session(TLSSessionCache *cache, SSL_SESSION *session, if (LOG_ENABLED(INFO)) { LOG(INFO) << "Update client cache entry " - << "timestamp = " << std::fixed << std::setprecision(6) << t; + << "timestamp = " << t; } cache->session_data = serialize_ssl_session(session);