src/shrpx_log.cc

   1 /*
   2  * nghttp2 - HTTP/2 C Library
   3  *
   4  * Copyright (c) 2012 Tatsuhiro Tsujikawa
   5  *
   6  * Permission is hereby granted, free of charge, to any person obtaining
   7  * a copy of this software and associated documentation files (the
   8  * "Software"), to deal in the Software without restriction, including
   9  * without limitation the rights to use, copy, modify, merge, publish,
  10  * distribute, sublicense, and/or sell copies of the Software, and to
  11  * permit persons to whom the Software is furnished to do so, subject to
  12  * the following conditions:
  13  *
  14  * The above copyright notice and this permission notice shall be
  15  * included in all copies or substantial portions of the Software.
  16  *
  17  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
  18  * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
  19  * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
  20  * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
  21  * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
  22  * OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
  23  * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
  24  */
  25 #include "shrpx_log.h"
  26
  27 #ifdef HAVE_SYSLOG_H
  28 #  include <syslog.h>
  29 #endif // HAVE_SYSLOG_H
  30 #ifdef HAVE_UNISTD_H
  31 #  include <unistd.h>
  32 #endif // HAVE_UNISTD_H
  33 #ifdef HAVE_INTTYPES_H
  34 #  include <inttypes.h>
  35 #endif // HAVE_INTTYPES_H
  36 #include <sys/types.h>
  37 #include <sys/stat.h>
  38 #ifdef HAVE_FCNTL_H
  39 #  include <fcntl.h>
  40 #endif // HAVE_FCNTL_H
  41 #include <sys/wait.h>
  42
  43 #include <cerrno>
  44 #include <cstdio>
  45 #include <cstring>
  46 #include <ctime>
  47 #include <iostream>
  48 #include <iomanip>
  49
  50 #include "shrpx_config.h"
  51 #include "shrpx_downstream.h"
  52 #include "shrpx_worker.h"
  53 #include "util.h"
  54 #include "template.h"
  55
  56 using namespace nghttp2;
  57
  58 namespace shrpx {
  59
  60 namespace {
  61 constexpr StringRef SEVERITY_STR[] = {
  62     StringRef::from_lit("INFO"), StringRef::from_lit("NOTICE"),
  63     StringRef::from_lit("WARN"), StringRef::from_lit("ERROR"),
  64     StringRef::from_lit("FATAL")};
  65 } // namespace
  66
  67 namespace {
  68 constexpr const char *SEVERITY_COLOR[] = {
  69     "\033[1;32m", // INFO
  70     "\033[1;36m", // NOTICE
  71     "\033[1;33m", // WARN
  72     "\033[1;31m", // ERROR
  73     "\033[1;35m", // FATAL
  74 };
  75 } // namespace
  76
  77 #ifndef NOTHREADS
  78 #  ifdef HAVE_THREAD_LOCAL
  79 namespace {
  80 thread_local LogBuffer logbuf_;
  81 } // namespace
  82
  83 namespace {
  84 LogBuffer *get_logbuf() { return &logbuf_; }
  85 } // namespace
  86 #  else  // !HAVE_THREAD_LOCAL
  87 namespace {
  88 pthread_key_t lckey;
  89 pthread_once_t lckey_once = PTHREAD_ONCE_INIT;
  90 } // namespace
  91
  92 namespace {
  93 void make_key() { pthread_key_create(&lckey, NULL); }
  94 } // namespace
  95
  96 LogBuffer *get_logbuf() {
  97   pthread_once(&lckey_once, make_key);
  98   auto buf = static_cast<LogBuffer *>(pthread_getspecific(lckey));
  99   if (!buf) {
 100     buf = new LogBuffer();
 101     pthread_setspecific(lckey, buf);
 102   }
 103   return buf;
 104 }
 105 #  endif // !HAVE_THREAD_LOCAL
 106 #else    // NOTHREADS
 107 namespace {
 108 LogBuffer *get_logbuf() {
 109   static LogBuffer logbuf;
 110   return &logbuf;
 111 }
 112 } // namespace
 113 #endif   // NOTHREADS
 114
 115 int Log::severity_thres_ = NOTICE;
 116
 117 void Log::set_severity_level(int severity) { severity_thres_ = severity; }
 118
 119 int Log::get_severity_level_by_name(const StringRef &name) {
 120   for (size_t i = 0, max = array_size(SEVERITY_STR); i < max; ++i) {
 121     if (name == SEVERITY_STR[i]) {
 122       return i;
 123     }
 124   }
 125   return -1;
 126 }
 127
 128 int severity_to_syslog_level(int severity) {
 129   switch (severity) {
 130   case (INFO):
 131     return LOG_INFO;
 132   case (NOTICE):
 133     return LOG_NOTICE;
 134   case (WARN):
 135     return LOG_WARNING;
 136   case (ERROR):
 137     return LOG_ERR;
 138   case (FATAL):
 139     return LOG_CRIT;
 140   default:
 141     return -1;
 142   }
 143 }
 144
 145 Log::Log(int severity, const char *filename, int linenum)
 146     : buf_(*get_logbuf()),
 147       begin_(buf_.data()),
 148       end_(begin_ + buf_.size()),
 149       last_(begin_),
 150       filename_(filename),
 151       flags_(0),
 152       severity_(severity),
 153       linenum_(linenum),
 154       full_(false) {}
 155
 156 Log::~Log() {
 157   int rv;
 158   auto config = get_config();
 159
 160   if (!config) {
 161     return;
 162   }
 163
 164   auto lgconf = log_config();
 165
 166   auto &errorconf = config->logging.error;
 167
 168   if (!log_enabled(severity_) ||
 169       (lgconf->errorlog_fd == -1 && !errorconf.syslog)) {
 170     return;
 171   }
 172
 173   if (errorconf.syslog) {
 174     if (severity_ == NOTICE) {
 175       syslog(severity_to_syslog_level(severity_), "[%s] %.*s",
 176              SEVERITY_STR[severity_].c_str(), static_cast<int>(rleft()),
 177              begin_);
 178     } else {
 179       syslog(severity_to_syslog_level(severity_), "[%s] %.*s (%s:%d)",
 180              SEVERITY_STR[severity_].c_str(), static_cast<int>(rleft()), begin_,
 181              filename_, linenum_);
 182     }
 183
 184     return;
 185   }
 186
 187   char buf[4_k];
 188   auto tty = lgconf->errorlog_tty;
 189
 190   lgconf->update_tstamp_millis(std::chrono::system_clock::now());
 191
 192   // Error log format: <datetime> <main-pid> <current-pid>
 193   // <thread-id> <level> (<filename>:<line>) <msg>
 194   rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %.*s\n",
 195                 lgconf->tstamp->time_iso8601.c_str(), config->pid, lgconf->pid,
 196                 lgconf->thread_id.c_str(), tty ? SEVERITY_COLOR[severity_] : "",
 197                 SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
 198                 filename_, linenum_, static_cast<int>(rleft()), begin_);
 199
 200   if (rv < 0) {
 201     return;
 202   }
 203
 204   auto nwrite = std::min(static_cast<size_t>(rv), sizeof(buf) - 1);
 205
 206   while (write(lgconf->errorlog_fd, buf, nwrite) == -1 && errno == EINTR)
 207     ;
 208 }
 209
 210 Log &Log::operator<<(const std::string &s) {
 211   write_seq(std::begin(s), std::end(s));
 212   return *this;
 213 }
 214
 215 Log &Log::operator<<(const StringRef &s) {
 216   write_seq(std::begin(s), std::end(s));
 217   return *this;
 218 }
 219
 220 Log &Log::operator<<(const char *s) {
 221   write_seq(s, s + strlen(s));
 222   return *this;
 223 }
 224
 225 Log &Log::operator<<(const ImmutableString &s) {
 226   write_seq(std::begin(s), std::end(s));
 227   return *this;
 228 }
 229
 230 Log &Log::operator<<(long long n) {
 231   if (n >= 0) {
 232     return *this << static_cast<uint64_t>(n);
 233   }
 234
 235   if (flags_ & fmt_hex) {
 236     write_hex(n);
 237     return *this;
 238   }
 239
 240   if (full_) {
 241     return *this;
 242   }
 243
 244   n *= -1;
 245
 246   size_t nlen = 0;
 247   for (auto t = n; t; t /= 10, ++nlen)
 248     ;
 249   if (wleft() < 1 /* sign */ + nlen) {
 250     full_ = true;
 251     return *this;
 252   }
 253   *last_++ = '-';
 254   last_ += nlen;
 255   update_full();
 256
 257   auto p = last_ - 1;
 258   for (; n; n /= 10) {
 259     *p-- = (n % 10) + '0';
 260   }
 261   return *this;
 262 }
 263
 264 Log &Log::operator<<(unsigned long long n) {
 265   if (flags_ & fmt_hex) {
 266     write_hex(n);
 267     return *this;
 268   }
 269
 270   if (full_) {
 271     return *this;
 272   }
 273
 274   if (n == 0) {
 275     *last_++ = '0';
 276     update_full();
 277     return *this;
 278   }
 279   size_t nlen = 0;
 280   for (auto t = n; t; t /= 10, ++nlen)
 281     ;
 282   if (wleft() < nlen) {
 283     full_ = true;
 284     return *this;
 285   }
 286
 287   last_ += nlen;
 288   update_full();
 289
 290   auto p = last_ - 1;
 291   for (; n; n /= 10) {
 292     *p-- = (n % 10) + '0';
 293   }
 294   return *this;
 295 }
 296
 297 Log &Log::operator<<(double n) {
 298   if (full_) {
 299     return *this;
 300   }
 301
 302   auto left = wleft();
 303   auto rv = snprintf(reinterpret_cast<char *>(last_), left, "%.9f", n);
 304   if (rv > static_cast<int>(left)) {
 305     full_ = true;
 306     return *this;
 307   }
 308
 309   last_ += rv;
 310   update_full();
 311
 312   return *this;
 313 }
 314
 315 Log &Log::operator<<(long double n) {
 316   if (full_) {
 317     return *this;
 318   }
 319
 320   auto left = wleft();
 321   auto rv = snprintf(reinterpret_cast<char *>(last_), left, "%.9Lf", n);
 322   if (rv > static_cast<int>(left)) {
 323     full_ = true;
 324     return *this;
 325   }
 326
 327   last_ += rv;
 328   update_full();
 329
 330   return *this;
 331 }
 332
 333 Log &Log::operator<<(bool n) {
 334   if (full_) {
 335     return *this;
 336   }
 337
 338   *last_++ = n ? '1' : '0';
 339   update_full();
 340
 341   return *this;
 342 }
 343
 344 Log &Log::operator<<(const void *p) {
 345   if (full_) {
 346     return *this;
 347   }
 348
 349   write_hex(reinterpret_cast<uintptr_t>(p));
 350
 351   return *this;
 352 }
 353
 354 namespace log {
 355 void hex(Log &log) { log.set_flags(Log::fmt_hex); };
 356
 357 void dec(Log &log) { log.set_flags(Log::fmt_dec); };
 358 } // namespace log
 359
 360 namespace {
 361 template <typename OutputIterator>
 362 std::pair<OutputIterator, OutputIterator> copy(const char *src, size_t srclen,
 363                                                OutputIterator d_first,
 364                                                OutputIterator d_last) {
 365   auto nwrite =
 366       std::min(static_cast<size_t>(std::distance(d_first, d_last)), srclen);
 367   return std::make_pair(std::copy_n(src, nwrite, d_first), d_last);
 368 }
 369 } // namespace
 370
 371 namespace {
 372 template <typename OutputIterator>
 373 std::pair<OutputIterator, OutputIterator>
 374 copy(const char *src, OutputIterator d_first, OutputIterator d_last) {
 375   return copy(src, strlen(src), d_first, d_last);
 376 }
 377 } // namespace
 378
 379 namespace {
 380 template <typename OutputIterator>
 381 std::pair<OutputIterator, OutputIterator>
 382 copy(const StringRef &src, OutputIterator d_first, OutputIterator d_last) {
 383   return copy(src.c_str(), src.size(), d_first, d_last);
 384 }
 385 } // namespace
 386
 387 namespace {
 388 template <size_t N, typename OutputIterator>
 389 std::pair<OutputIterator, OutputIterator>
 390 copy_l(const char (&src)[N], OutputIterator d_first, OutputIterator d_last) {
 391   return copy(src, N - 1, d_first, d_last);
 392 }
 393 } // namespace
 394
 395 namespace {
 396 template <typename OutputIterator>
 397 std::pair<OutputIterator, OutputIterator> copy(char c, OutputIterator d_first,
 398                                                OutputIterator d_last) {
 399   if (d_first == d_last) {
 400     return std::make_pair(d_last, d_last);
 401   }
 402   *d_first++ = c;
 403   return std::make_pair(d_first, d_last);
 404 }
 405 } // namespace
 406
 407 namespace {
 408 constexpr char LOWER_XDIGITS[] = "0123456789abcdef";
 409 } // namespace
 410
 411 namespace {
 412 template <typename OutputIterator>
 413 std::pair<OutputIterator, OutputIterator>
 414 copy_hex_low(const uint8_t *src, size_t srclen, OutputIterator d_first,
 415              OutputIterator d_last) {
 416   auto nwrite = std::min(static_cast<size_t>(std::distance(d_first, d_last)),
 417                          srclen * 2) /
 418                 2;
 419   for (size_t i = 0; i < nwrite; ++i) {
 420     *d_first++ = LOWER_XDIGITS[src[i] >> 4];
 421     *d_first++ = LOWER_XDIGITS[src[i] & 0xf];
 422   }
 423   return std::make_pair(d_first, d_last);
 424 }
 425 } // namespace
 426
 427 namespace {
 428 template <typename OutputIterator, typename T>
 429 std::pair<OutputIterator, OutputIterator> copy(T n, OutputIterator d_first,
 430                                                OutputIterator d_last) {
 431   if (static_cast<size_t>(std::distance(d_first, d_last)) <
 432       NGHTTP2_MAX_UINT64_DIGITS) {
 433     return std::make_pair(d_last, d_last);
 434   }
 435   return std::make_pair(util::utos(d_first, n), d_last);
 436 }
 437 } // namespace
 438
 439 namespace {
 440 // 1 means that character must be escaped as "\xNN", where NN is ascii
 441 // code of the character in hex notation.
 442 constexpr uint8_t ESCAPE_TBL[] = {
 443     1 /* NUL  */, 1 /* SOH  */, 1 /* STX  */, 1 /* ETX  */, 1 /* EOT  */,
 444     1 /* ENQ  */, 1 /* ACK  */, 1 /* BEL  */, 1 /* BS   */, 1 /* HT   */,
 445     1 /* LF   */, 1 /* VT   */, 1 /* FF   */, 1 /* CR   */, 1 /* SO   */,
 446     1 /* SI   */, 1 /* DLE  */, 1 /* DC1  */, 1 /* DC2  */, 1 /* DC3  */,
 447     1 /* DC4  */, 1 /* NAK  */, 1 /* SYN  */, 1 /* ETB  */, 1 /* CAN  */,
 448     1 /* EM   */, 1 /* SUB  */, 1 /* ESC  */, 1 /* FS   */, 1 /* GS   */,
 449     1 /* RS   */, 1 /* US   */, 0 /* SPC  */, 0 /* !    */, 1 /* "    */,
 450     0 /* #    */, 0 /* $    */, 0 /* %    */, 0 /* &    */, 0 /* '    */,
 451     0 /* (    */, 0 /* )    */, 0 /* *    */, 0 /* +    */, 0 /* ,    */,
 452     0 /* -    */, 0 /* .    */, 0 /* /    */, 0 /* 0    */, 0 /* 1    */,
 453     0 /* 2    */, 0 /* 3    */, 0 /* 4    */, 0 /* 5    */, 0 /* 6    */,
 454     0 /* 7    */, 0 /* 8    */, 0 /* 9    */, 0 /* :    */, 0 /* ;    */,
 455     0 /* <    */, 0 /* =    */, 0 /* >    */, 0 /* ?    */, 0 /* @    */,
 456     0 /* A    */, 0 /* B    */, 0 /* C    */, 0 /* D    */, 0 /* E    */,
 457     0 /* F    */, 0 /* G    */, 0 /* H    */, 0 /* I    */, 0 /* J    */,
 458     0 /* K    */, 0 /* L    */, 0 /* M    */, 0 /* N    */, 0 /* O    */,
 459     0 /* P    */, 0 /* Q    */, 0 /* R    */, 0 /* S    */, 0 /* T    */,
 460     0 /* U    */, 0 /* V    */, 0 /* W    */, 0 /* X    */, 0 /* Y    */,
 461     0 /* Z    */, 0 /* [    */, 1 /* \    */, 0 /* ]    */, 0 /* ^    */,
 462     0 /* _    */, 0 /* `    */, 0 /* a    */, 0 /* b    */, 0 /* c    */,
 463     0 /* d    */, 0 /* e    */, 0 /* f    */, 0 /* g    */, 0 /* h    */,
 464     0 /* i    */, 0 /* j    */, 0 /* k    */, 0 /* l    */, 0 /* m    */,
 465     0 /* n    */, 0 /* o    */, 0 /* p    */, 0 /* q    */, 0 /* r    */,
 466     0 /* s    */, 0 /* t    */, 0 /* u    */, 0 /* v    */, 0 /* w    */,
 467     0 /* x    */, 0 /* y    */, 0 /* z    */, 0 /* {    */, 0 /* |    */,
 468     0 /* }    */, 0 /* ~    */, 1 /* DEL  */, 1 /* 0x80 */, 1 /* 0x81 */,
 469     1 /* 0x82 */, 1 /* 0x83 */, 1 /* 0x84 */, 1 /* 0x85 */, 1 /* 0x86 */,
 470     1 /* 0x87 */, 1 /* 0x88 */, 1 /* 0x89 */, 1 /* 0x8a */, 1 /* 0x8b */,
 471     1 /* 0x8c */, 1 /* 0x8d */, 1 /* 0x8e */, 1 /* 0x8f */, 1 /* 0x90 */,
 472     1 /* 0x91 */, 1 /* 0x92 */, 1 /* 0x93 */, 1 /* 0x94 */, 1 /* 0x95 */,
 473     1 /* 0x96 */, 1 /* 0x97 */, 1 /* 0x98 */, 1 /* 0x99 */, 1 /* 0x9a */,
 474     1 /* 0x9b */, 1 /* 0x9c */, 1 /* 0x9d */, 1 /* 0x9e */, 1 /* 0x9f */,
 475     1 /* 0xa0 */, 1 /* 0xa1 */, 1 /* 0xa2 */, 1 /* 0xa3 */, 1 /* 0xa4 */,
 476     1 /* 0xa5 */, 1 /* 0xa6 */, 1 /* 0xa7 */, 1 /* 0xa8 */, 1 /* 0xa9 */,
 477     1 /* 0xaa */, 1 /* 0xab */, 1 /* 0xac */, 1 /* 0xad */, 1 /* 0xae */,
 478     1 /* 0xaf */, 1 /* 0xb0 */, 1 /* 0xb1 */, 1 /* 0xb2 */, 1 /* 0xb3 */,
 479     1 /* 0xb4 */, 1 /* 0xb5 */, 1 /* 0xb6 */, 1 /* 0xb7 */, 1 /* 0xb8 */,
 480     1 /* 0xb9 */, 1 /* 0xba */, 1 /* 0xbb */, 1 /* 0xbc */, 1 /* 0xbd */,
 481     1 /* 0xbe */, 1 /* 0xbf */, 1 /* 0xc0 */, 1 /* 0xc1 */, 1 /* 0xc2 */,
 482     1 /* 0xc3 */, 1 /* 0xc4 */, 1 /* 0xc5 */, 1 /* 0xc6 */, 1 /* 0xc7 */,
 483     1 /* 0xc8 */, 1 /* 0xc9 */, 1 /* 0xca */, 1 /* 0xcb */, 1 /* 0xcc */,
 484     1 /* 0xcd */, 1 /* 0xce */, 1 /* 0xcf */, 1 /* 0xd0 */, 1 /* 0xd1 */,
 485     1 /* 0xd2 */, 1 /* 0xd3 */, 1 /* 0xd4 */, 1 /* 0xd5 */, 1 /* 0xd6 */,
 486     1 /* 0xd7 */, 1 /* 0xd8 */, 1 /* 0xd9 */, 1 /* 0xda */, 1 /* 0xdb */,
 487     1 /* 0xdc */, 1 /* 0xdd */, 1 /* 0xde */, 1 /* 0xdf */, 1 /* 0xe0 */,
 488     1 /* 0xe1 */, 1 /* 0xe2 */, 1 /* 0xe3 */, 1 /* 0xe4 */, 1 /* 0xe5 */,
 489     1 /* 0xe6 */, 1 /* 0xe7 */, 1 /* 0xe8 */, 1 /* 0xe9 */, 1 /* 0xea */,
 490     1 /* 0xeb */, 1 /* 0xec */, 1 /* 0xed */, 1 /* 0xee */, 1 /* 0xef */,
 491     1 /* 0xf0 */, 1 /* 0xf1 */, 1 /* 0xf2 */, 1 /* 0xf3 */, 1 /* 0xf4 */,
 492     1 /* 0xf5 */, 1 /* 0xf6 */, 1 /* 0xf7 */, 1 /* 0xf8 */, 1 /* 0xf9 */,
 493     1 /* 0xfa */, 1 /* 0xfb */, 1 /* 0xfc */, 1 /* 0xfd */, 1 /* 0xfe */,
 494     1 /* 0xff */,
 495 };
 496 } // namespace
 497
 498 namespace {
 499 template <typename OutputIterator>
 500 std::pair<OutputIterator, OutputIterator>
 501 copy_escape(const char *src, size_t srclen, OutputIterator d_first,
 502             OutputIterator d_last) {
 503   auto safe_first = src;
 504   for (auto p = src; p != src + srclen && d_first != d_last; ++p) {
 505     unsigned char c = *p;
 506     if (!ESCAPE_TBL[c]) {
 507       continue;
 508     }
 509
 510     auto n =
 511         std::min(std::distance(d_first, d_last), std::distance(safe_first, p));
 512     d_first = std::copy_n(safe_first, n, d_first);
 513     if (std::distance(d_first, d_last) < 4) {
 514       return std::make_pair(d_first, d_last);
 515     }
 516     *d_first++ = '\\';
 517     *d_first++ = 'x';
 518     *d_first++ = LOWER_XDIGITS[c >> 4];
 519     *d_first++ = LOWER_XDIGITS[c & 0xf];
 520     safe_first = p + 1;
 521   }
 522
 523   auto n = std::min(std::distance(d_first, d_last),
 524                     std::distance(safe_first, src + srclen));
 525   return std::make_pair(std::copy_n(safe_first, n, d_first), d_last);
 526 }
 527 } // namespace
 528
 529 namespace {
 530 template <typename OutputIterator>
 531 std::pair<OutputIterator, OutputIterator> copy_escape(const StringRef &src,
 532                                                       OutputIterator d_first,
 533                                                       OutputIterator d_last) {
 534   return copy_escape(src.c_str(), src.size(), d_first, d_last);
 535 }
 536 } // namespace
 537
 538 namespace {
 539 // Construct absolute request URI from |Request|, mainly to log
 540 // request URI for proxy request (HTTP/2 proxy or client proxy).  This
 541 // is mostly same routine found in
 542 // HttpDownstreamConnection::push_request_headers(), but vastly
 543 // simplified since we only care about absolute URI.
 544 StringRef construct_absolute_request_uri(BlockAllocator &balloc,
 545                                          const Request &req) {
 546   if (req.authority.empty()) {
 547     return req.path;
 548   }
 549
 550   auto len = req.authority.size() + req.path.size();
 551   if (req.scheme.empty()) {
 552     len += str_size("http://");
 553   } else {
 554     len += req.scheme.size() + str_size("://");
 555   }
 556
 557   auto iov = make_byte_ref(balloc, len + 1);
 558   auto p = iov.base;
 559
 560   if (req.scheme.empty()) {
 561     // We may have to log the request which lacks scheme (e.g.,
 562     // http/1.1 with origin form).
 563     p = util::copy_lit(p, "http://");
 564   } else {
 565     p = std::copy(std::begin(req.scheme), std::end(req.scheme), p);
 566     p = util::copy_lit(p, "://");
 567   }
 568   p = std::copy(std::begin(req.authority), std::end(req.authority), p);
 569   p = std::copy(std::begin(req.path), std::end(req.path), p);
 570   *p = '\0';
 571
 572   return StringRef{iov.base, p};
 573 }
 574 } // namespace
 575
 576 void upstream_accesslog(const std::vector<LogFragment> &lfv,
 577                         const LogSpec &lgsp) {
 578   auto config = get_config();
 579   auto lgconf = log_config();
 580   auto &accessconf = get_config()->logging.access;
 581
 582   if (lgconf->accesslog_fd == -1 && !accessconf.syslog) {
 583     return;
 584   }
 585
 586   std::array<char, 4_k> buf;
 587
 588   auto downstream = lgsp.downstream;
 589
 590   const auto &req = downstream->request();
 591   const auto &resp = downstream->response();
 592   const auto &tstamp = req.tstamp;
 593   auto &balloc = downstream->get_block_allocator();
 594
 595   auto downstream_addr = downstream->get_addr();
 596   auto method = req.method == -1 ? StringRef::from_lit("<unknown>")
 597                                  : http2::to_method_string(req.method);
 598   auto path =
 599       req.method == HTTP_CONNECT ? req.authority
 600       : config->http2_proxy      ? construct_absolute_request_uri(balloc, req)
 601       : req.path.empty() ? req.method == HTTP_OPTIONS ? StringRef::from_lit("*")
 602                                                       : StringRef::from_lit("-")
 603                          : req.path;
 604   auto path_without_query =
 605       req.method == HTTP_CONNECT
 606           ? path
 607           : StringRef{std::begin(path),
 608                       std::find(std::begin(path), std::end(path), '?')};
 609
 610   auto p = std::begin(buf);
 611   auto last = std::end(buf) - 2;
 612
 613   for (auto &lf : lfv) {
 614     switch (lf.type) {
 615     case LogFragmentType::LITERAL:
 616       std::tie(p, last) = copy(lf.value, p, last);
 617       break;
 618     case LogFragmentType::REMOTE_ADDR:
 619       std::tie(p, last) = copy(lgsp.remote_addr, p, last);
 620       break;
 621     case LogFragmentType::TIME_LOCAL:
 622       std::tie(p, last) = copy(tstamp->time_local, p, last);
 623       break;
 624     case LogFragmentType::TIME_ISO8601:
 625       std::tie(p, last) = copy(tstamp->time_iso8601, p, last);
 626       break;
 627     case LogFragmentType::REQUEST:
 628       std::tie(p, last) = copy(method, p, last);
 629       std::tie(p, last) = copy(' ', p, last);
 630       std::tie(p, last) = copy_escape(path, p, last);
 631       std::tie(p, last) = copy_l(" HTTP/", p, last);
 632       std::tie(p, last) = copy(req.http_major, p, last);
 633       if (req.http_major < 2) {
 634         std::tie(p, last) = copy('.', p, last);
 635         std::tie(p, last) = copy(req.http_minor, p, last);
 636       }
 637       break;
 638     case LogFragmentType::METHOD:
 639       std::tie(p, last) = copy(method, p, last);
 640       break;
 641     case LogFragmentType::PATH:
 642       std::tie(p, last) = copy_escape(path, p, last);
 643       break;
 644     case LogFragmentType::PATH_WITHOUT_QUERY:
 645       std::tie(p, last) = copy_escape(path_without_query, p, last);
 646       break;
 647     case LogFragmentType::PROTOCOL_VERSION:
 648       std::tie(p, last) = copy_l("HTTP/", p, last);
 649       std::tie(p, last) = copy(req.http_major, p, last);
 650       if (req.http_major < 2) {
 651         std::tie(p, last) = copy('.', p, last);
 652         std::tie(p, last) = copy(req.http_minor, p, last);
 653       }
 654       break;
 655     case LogFragmentType::STATUS:
 656       std::tie(p, last) = copy(resp.http_status, p, last);
 657       break;
 658     case LogFragmentType::BODY_BYTES_SENT:
 659       std::tie(p, last) = copy(downstream->response_sent_body_length, p, last);
 660       break;
 661     case LogFragmentType::HTTP: {
 662       auto hd = req.fs.header(lf.value);
 663       if (hd) {
 664         std::tie(p, last) = copy_escape((*hd).value, p, last);
 665         break;
 666       }
 667
 668       std::tie(p, last) = copy('-', p, last);
 669
 670       break;
 671     }
 672     case LogFragmentType::AUTHORITY:
 673       if (!req.authority.empty()) {
 674         std::tie(p, last) = copy(req.authority, p, last);
 675         break;
 676       }
 677
 678       std::tie(p, last) = copy('-', p, last);
 679
 680       break;
 681     case LogFragmentType::REMOTE_PORT:
 682       std::tie(p, last) = copy(lgsp.remote_port, p, last);
 683       break;
 684     case LogFragmentType::SERVER_PORT:
 685       std::tie(p, last) = copy(lgsp.server_port, p, last);
 686       break;
 687     case LogFragmentType::REQUEST_TIME: {
 688       auto t = std::chrono::duration_cast<std::chrono::milliseconds>(
 689                    lgsp.request_end_time - downstream->get_request_start_time())
 690                    .count();
 691       std::tie(p, last) = copy(t / 1000, p, last);
 692       std::tie(p, last) = copy('.', p, last);
 693       auto frac = t % 1000;
 694       if (frac < 100) {
 695         auto n = frac < 10 ? 2 : 1;
 696         std::tie(p, last) = copy("000", n, p, last);
 697       }
 698       std::tie(p, last) = copy(frac, p, last);
 699       break;
 700     }
 701     case LogFragmentType::PID:
 702       std::tie(p, last) = copy(lgsp.pid, p, last);
 703       break;
 704     case LogFragmentType::ALPN:
 705       std::tie(p, last) = copy_escape(lgsp.alpn, p, last);
 706       break;
 707     case LogFragmentType::TLS_CIPHER:
 708       if (!lgsp.ssl) {
 709         std::tie(p, last) = copy('-', p, last);
 710         break;
 711       }
 712       std::tie(p, last) = copy(SSL_get_cipher_name(lgsp.ssl), p, last);
 713       break;
 714     case LogFragmentType::TLS_PROTOCOL:
 715       if (!lgsp.ssl) {
 716         std::tie(p, last) = copy('-', p, last);
 717         break;
 718       }
 719       std::tie(p, last) =
 720           copy(nghttp2::tls::get_tls_protocol(lgsp.ssl), p, last);
 721       break;
 722     case LogFragmentType::TLS_SESSION_ID: {
 723       auto session = SSL_get_session(lgsp.ssl);
 724       if (!session) {
 725         std::tie(p, last) = copy('-', p, last);
 726         break;
 727       }
 728       unsigned int session_id_length = 0;
 729       auto session_id = SSL_SESSION_get_id(session, &session_id_length);
 730       if (session_id_length == 0) {
 731         std::tie(p, last) = copy('-', p, last);
 732         break;
 733       }
 734       std::tie(p, last) = copy_hex_low(session_id, session_id_length, p, last);
 735       break;
 736     }
 737     case LogFragmentType::TLS_SESSION_REUSED:
 738       if (!lgsp.ssl) {
 739         std::tie(p, last) = copy('-', p, last);
 740         break;
 741       }
 742       std::tie(p, last) =
 743           copy(SSL_session_reused(lgsp.ssl) ? 'r' : '.', p, last);
 744       break;
 745     case LogFragmentType::TLS_SNI:
 746       if (lgsp.sni.empty()) {
 747         std::tie(p, last) = copy('-', p, last);
 748         break;
 749       }
 750       std::tie(p, last) = copy_escape(lgsp.sni, p, last);
 751       break;
 752     case LogFragmentType::TLS_CLIENT_FINGERPRINT_SHA1:
 753     case LogFragmentType::TLS_CLIENT_FINGERPRINT_SHA256: {
 754       if (!lgsp.ssl) {
 755         std::tie(p, last) = copy('-', p, last);
 756         break;
 757       }
 758 #if OPENSSL_3_0_0_API
 759       auto x = SSL_get0_peer_certificate(lgsp.ssl);
 760 #else  // !OPENSSL_3_0_0_API
 761       auto x = SSL_get_peer_certificate(lgsp.ssl);
 762 #endif // !OPENSSL_3_0_0_API
 763       if (!x) {
 764         std::tie(p, last) = copy('-', p, last);
 765         break;
 766       }
 767       std::array<uint8_t, 32> buf;
 768       auto len = tls::get_x509_fingerprint(
 769           buf.data(), buf.size(), x,
 770           lf.type == LogFragmentType::TLS_CLIENT_FINGERPRINT_SHA256
 771               ? EVP_sha256()
 772               : EVP_sha1());
 773 #if !OPENSSL_3_0_0_API
 774       X509_free(x);
 775 #endif // !OPENSSL_3_0_0_API
 776       if (len <= 0) {
 777         std::tie(p, last) = copy('-', p, last);
 778         break;
 779       }
 780       std::tie(p, last) = copy_hex_low(buf.data(), len, p, last);
 781       break;
 782     }
 783     case LogFragmentType::TLS_CLIENT_ISSUER_NAME:
 784     case LogFragmentType::TLS_CLIENT_SUBJECT_NAME: {
 785       if (!lgsp.ssl) {
 786         std::tie(p, last) = copy('-', p, last);
 787         break;
 788       }
 789 #if OPENSSL_3_0_0_API
 790       auto x = SSL_get0_peer_certificate(lgsp.ssl);
 791 #else  // !OPENSSL_3_0_0_API
 792       auto x = SSL_get_peer_certificate(lgsp.ssl);
 793 #endif // !OPENSSL_3_0_0_API
 794       if (!x) {
 795         std::tie(p, last) = copy('-', p, last);
 796         break;
 797       }
 798       auto name = lf.type == LogFragmentType::TLS_CLIENT_ISSUER_NAME
 799                       ? tls::get_x509_issuer_name(balloc, x)
 800                       : tls::get_x509_subject_name(balloc, x);
 801 #if !OPENSSL_3_0_0_API
 802       X509_free(x);
 803 #endif // !OPENSSL_3_0_0_API
 804       if (name.empty()) {
 805         std::tie(p, last) = copy('-', p, last);
 806         break;
 807       }
 808       std::tie(p, last) = copy(name, p, last);
 809       break;
 810     }
 811     case LogFragmentType::TLS_CLIENT_SERIAL: {
 812       if (!lgsp.ssl) {
 813         std::tie(p, last) = copy('-', p, last);
 814         break;
 815       }
 816 #if OPENSSL_3_0_0_API
 817       auto x = SSL_get0_peer_certificate(lgsp.ssl);
 818 #else  // !OPENSSL_3_0_0_API
 819       auto x = SSL_get_peer_certificate(lgsp.ssl);
 820 #endif // !OPENSSL_3_0_0_API
 821       if (!x) {
 822         std::tie(p, last) = copy('-', p, last);
 823         break;
 824       }
 825       auto sn = tls::get_x509_serial(balloc, x);
 826 #if !OPENSSL_3_0_0_API
 827       X509_free(x);
 828 #endif // !OPENSSL_3_0_0_API
 829       if (sn.empty()) {
 830         std::tie(p, last) = copy('-', p, last);
 831         break;
 832       }
 833       std::tie(p, last) = copy(sn, p, last);
 834       break;
 835     }
 836     case LogFragmentType::BACKEND_HOST:
 837       if (!downstream_addr) {
 838         std::tie(p, last) = copy('-', p, last);
 839         break;
 840       }
 841       std::tie(p, last) = copy(downstream_addr->host, p, last);
 842       break;
 843     case LogFragmentType::BACKEND_PORT:
 844       if (!downstream_addr) {
 845         std::tie(p, last) = copy('-', p, last);
 846         break;
 847       }
 848       std::tie(p, last) = copy(downstream_addr->port, p, last);
 849       break;
 850     case LogFragmentType::NONE:
 851       break;
 852     default:
 853       break;
 854     }
 855   }
 856
 857   *p = '\0';
 858
 859   if (accessconf.syslog) {
 860     syslog(LOG_INFO, "%s", buf.data());
 861
 862     return;
 863   }
 864
 865   *p++ = '\n';
 866
 867   auto nwrite = std::distance(std::begin(buf), p);
 868   while (write(lgconf->accesslog_fd, buf.data(), nwrite) == -1 &&
 869          errno == EINTR)
 870     ;
 871 }
 872
 873 int reopen_log_files(const LoggingConfig &loggingconf) {
 874   int res = 0;
 875   int new_accesslog_fd = -1;
 876   int new_errorlog_fd = -1;
 877
 878   auto lgconf = log_config();
 879   auto &accessconf = loggingconf.access;
 880   auto &errorconf = loggingconf.error;
 881
 882   if (!accessconf.syslog && !accessconf.file.empty()) {
 883     new_accesslog_fd = open_log_file(accessconf.file.c_str());
 884
 885     if (new_accesslog_fd == -1) {
 886       LOG(ERROR) << "Failed to open accesslog file " << accessconf.file;
 887       res = -1;
 888     }
 889   }
 890
 891   if (!errorconf.syslog && !errorconf.file.empty()) {
 892     new_errorlog_fd = open_log_file(errorconf.file.c_str());
 893
 894     if (new_errorlog_fd == -1) {
 895       if (lgconf->errorlog_fd != -1) {
 896         LOG(ERROR) << "Failed to open errorlog file " << errorconf.file;
 897       } else {
 898         std::cerr << "Failed to open errorlog file " << errorconf.file
 899                   << std::endl;
 900       }
 901
 902       res = -1;
 903     }
 904   }
 905
 906   close_log_file(lgconf->accesslog_fd);
 907   close_log_file(lgconf->errorlog_fd);
 908
 909   lgconf->accesslog_fd = new_accesslog_fd;
 910   lgconf->errorlog_fd = new_errorlog_fd;
 911   lgconf->errorlog_tty =
 912       (new_errorlog_fd == -1) ? false : isatty(new_errorlog_fd);
 913
 914   return res;
 915 }
 916
 917 void log_chld(pid_t pid, int rstatus, const char *msg) {
 918   std::string signalstr;
 919   if (WIFSIGNALED(rstatus)) {
 920     signalstr += "; signal ";
 921     auto sig = WTERMSIG(rstatus);
 922     auto s = strsignal(sig);
 923     if (s) {
 924       signalstr += s;
 925       signalstr += '(';
 926     } else {
 927       signalstr += "UNKNOWN(";
 928     }
 929     signalstr += util::utos(sig);
 930     signalstr += ')';
 931   }
 932
 933   LOG(NOTICE) << msg << ": [" << pid << "] exited "
 934               << (WIFEXITED(rstatus) ? "normally" : "abnormally")
 935               << " with status " << log::hex << rstatus << log::dec
 936               << "; exit status "
 937               << (WIFEXITED(rstatus) ? WEXITSTATUS(rstatus) : 0)
 938               << (signalstr.empty() ? "" : signalstr.c_str());
 939 }
 940
 941 void redirect_stderr_to_errorlog(const LoggingConfig &loggingconf) {
 942   auto lgconf = log_config();
 943   auto &errorconf = loggingconf.error;
 944
 945   if (errorconf.syslog || lgconf->errorlog_fd == -1) {
 946     return;
 947   }
 948
 949   dup2(lgconf->errorlog_fd, STDERR_FILENO);
 950 }
 951
 952 namespace {
 953 int STDERR_COPY = -1;
 954 int STDOUT_COPY = -1;
 955 } // namespace
 956
 957 void store_original_fds() {
 958   // consider dup'ing stdout too
 959   STDERR_COPY = dup(STDERR_FILENO);
 960   STDOUT_COPY = STDOUT_FILENO;
 961   // no race here, since it is called early
 962   util::make_socket_closeonexec(STDERR_COPY);
 963 }
 964
 965 void restore_original_fds() { dup2(STDERR_COPY, STDERR_FILENO); }
 966
 967 void close_log_file(int &fd) {
 968   if (fd != STDERR_COPY && fd != STDOUT_COPY && fd != -1) {
 969     close(fd);
 970   }
 971   fd = -1;
 972 }
 973
 974 int open_log_file(const char *path) {
 975
 976   if (strcmp(path, "/dev/stdout") == 0 ||
 977       strcmp(path, "/proc/self/fd/1") == 0) {
 978     return STDOUT_COPY;
 979   }
 980
 981   if (strcmp(path, "/dev/stderr") == 0 ||
 982       strcmp(path, "/proc/self/fd/2") == 0) {
 983     return STDERR_COPY;
 984   }
 985 #ifdef O_CLOEXEC
 986
 987   auto fd = open(path, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC,
 988                  S_IRUSR | S_IWUSR | S_IRGRP);
 989 #else // !O_CLOEXEC
 990
 991   auto fd =
 992       open(path, O_WRONLY | O_APPEND | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP);
 993
 994   // We get race condition if execve is called at the same time.
 995   if (fd != -1) {
 996     util::make_socket_closeonexec(fd);
 997   }
 998
 999 #endif // !O_CLOEXEC
1000
1001   if (fd == -1) {
1002     return -1;
1003   }
1004
1005   return fd;
1006 }
1007
1008 } // namespace shrpx