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 {
get_logbuf()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 {
make_key()93 void make_key() { pthread_key_create(&lckey, NULL); }
94 } // namespace
95 
get_logbuf()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 {
get_logbuf()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 
set_severity_level(int severity)117 void Log::set_severity_level(int severity) { severity_thres_ = severity; }
118 
get_severity_level_by_name(const StringRef & name)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 
severity_to_syslog_level(int severity)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 
Log(int severity,const char * filename,int linenum)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 
~Log()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 
operator <<(const std::string & s)210 Log &Log::operator<<(const std::string &s) {
211   write_seq(std::begin(s), std::end(s));
212   return *this;
213 }
214 
operator <<(const StringRef & s)215 Log &Log::operator<<(const StringRef &s) {
216   write_seq(std::begin(s), std::end(s));
217   return *this;
218 }
219 
operator <<(const char * s)220 Log &Log::operator<<(const char *s) {
221   write_seq(s, s + strlen(s));
222   return *this;
223 }
224 
operator <<(const ImmutableString & s)225 Log &Log::operator<<(const ImmutableString &s) {
226   write_seq(std::begin(s), std::end(s));
227   return *this;
228 }
229 
operator <<(long long n)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 
operator <<(unsigned long long n)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 
operator <<(double n)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 
operator <<(long double n)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 
operator <<(bool n)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 
operator <<(const void * p)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 {
hex(Log & log)355 void hex(Log &log) { log.set_flags(Log::fmt_hex); };
356 
dec(Log & log)357 void dec(Log &log) { log.set_flags(Log::fmt_dec); };
358 } // namespace log
359 
360 namespace {
361 template <typename OutputIterator>
copy(const char * src,size_t srclen,OutputIterator d_first,OutputIterator d_last)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>
copy(const char * src,OutputIterator d_first,OutputIterator d_last)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>
copy(const StringRef & src,OutputIterator d_first,OutputIterator d_last)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>
copy_l(const char (& src)[N],OutputIterator d_first,OutputIterator d_last)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>
copy(char c,OutputIterator d_first,OutputIterator d_last)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>
copy_hex_low(const uint8_t * src,size_t srclen,OutputIterator d_first,OutputIterator d_last)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>
copy(T n,OutputIterator d_first,OutputIterator d_last)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>
copy_escape(const char * src,size_t srclen,OutputIterator d_first,OutputIterator d_last)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>
copy_escape(const StringRef & src,OutputIterator d_first,OutputIterator d_last)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.
construct_absolute_request_uri(BlockAllocator & balloc,const Request & req)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 
upstream_accesslog(const std::vector<LogFragment> & lfv,const LogSpec & lgsp)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 
reopen_log_files(const LoggingConfig & loggingconf)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 
log_chld(pid_t pid,int rstatus,const char * msg)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 
redirect_stderr_to_errorlog(const LoggingConfig & loggingconf)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 
store_original_fds()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 
restore_original_fds()965 void restore_original_fds() { dup2(STDERR_COPY, STDERR_FILENO); }
966 
close_log_file(int & fd)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 
open_log_file(const char * path)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
1009