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