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, nullptr); }
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