diff --git a/gennghttpxfun.py b/gennghttpxfun.py index 1f925915..337c1cb4 100755 --- a/gennghttpxfun.py +++ b/gennghttpxfun.py @@ -189,6 +189,7 @@ OPTIONS = [ "frontend-http3-max-connection-window-size", "frontend-http3-max-concurrent-streams", "frontend-quic-early-data", + "frontend-quic-qlog-dir", ] LOGVARS = [ diff --git a/src/shrpx.cc b/src/shrpx.cc index 42c5fe89..4938f5cf 100644 --- a/src/shrpx.cc +++ b/src/shrpx.cc @@ -3216,6 +3216,12 @@ HTTP/3 and QUIC: request is received in early data and handshake has not finished. All backend servers should deal with possibly replayed requests. + --frontend-quic-qlog-dir= + Specify a directory where a qlog file is written for + frontend QUIC connections. A qlog file is created per + each QUIC connection. The file name is ISO8601 basic + format, followed by "-", server Source Connection ID and + ".qlog". --no-quic-bpf Disable eBPF. --frontend-http3-window-size= @@ -4003,6 +4009,8 @@ int main(int argc, char **argv) { {SHRPX_OPT_FRONTEND_HTTP3_MAX_CONCURRENT_STREAMS.c_str(), required_argument, &flag, 179}, {SHRPX_OPT_FRONTEND_QUIC_EARLY_DATA.c_str(), no_argument, &flag, 180}, + {SHRPX_OPT_FRONTEND_QUIC_QLOG_DIR.c_str(), required_argument, &flag, + 181}, {nullptr, 0, nullptr, 0}}; int option_index = 0; @@ -4865,6 +4873,11 @@ int main(int argc, char **argv) { cmdcfgs.emplace_back(SHRPX_OPT_FRONTEND_QUIC_EARLY_DATA, StringRef::from_lit("yes")); break; + case 181: + // --frontend-quic-qlog-dir + cmdcfgs.emplace_back(SHRPX_OPT_FRONTEND_QUIC_QLOG_DIR, + StringRef{optarg}); + break; default: break; } diff --git a/src/shrpx_config.cc b/src/shrpx_config.cc index f9bdf279..356c4bca 100644 --- a/src/shrpx_config.cc +++ b/src/shrpx_config.cc @@ -2255,6 +2255,9 @@ int option_lookup_token(const char *name, size_t namelen) { if (util::strieq_l("backend-request-buffe", name, 21)) { return SHRPX_OPTID_BACKEND_REQUEST_BUFFER; } + if (util::strieq_l("frontend-quic-qlog-di", name, 21)) { + return SHRPX_OPTID_FRONTEND_QUIC_QLOG_DIR; + } break; case 't': if (util::strieq_l("frontend-write-timeou", name, 21)) { @@ -3977,6 +3980,12 @@ int parse_config(Config *config, int optid, const StringRef &opt, config->quic.upstream.early_data = util::strieq_l("yes", optarg); #endif // ENABLE_HTTP3 + return 0; + case SHRPX_OPTID_FRONTEND_QUIC_QLOG_DIR: +#ifdef ENABLE_HTTP3 + config->quic.upstream.qlog.dir = optarg; +#endif // ENABLE_HTTP3 + return 0; case SHRPX_OPTID_CONF: LOG(WARN) << "conf: ignored"; diff --git a/src/shrpx_config.h b/src/shrpx_config.h index 9b508293..fdb7bae0 100644 --- a/src/shrpx_config.h +++ b/src/shrpx_config.h @@ -385,6 +385,8 @@ constexpr auto SHRPX_OPT_FRONTEND_HTTP3_MAX_CONCURRENT_STREAMS = StringRef::from_lit("frontend-http3-max-concurrent-streams"); constexpr auto SHRPX_OPT_FRONTEND_QUIC_EARLY_DATA = StringRef::from_lit("frontend-quic-early-data"); +constexpr auto SHRPX_OPT_FRONTEND_QUIC_QLOG_DIR = + StringRef::from_lit("frontend-quic-qlog-dir"); constexpr size_t SHRPX_OBFUSCATED_NODE_LENGTH = 8; @@ -749,6 +751,9 @@ struct QUICConfig { struct { bool log; } debug; + struct { + StringRef dir; + } qlog; bool early_data; } upstream; struct { @@ -1205,6 +1210,7 @@ enum { SHRPX_OPTID_FRONTEND_QUIC_DEBUG_LOG, SHRPX_OPTID_FRONTEND_QUIC_EARLY_DATA, SHRPX_OPTID_FRONTEND_QUIC_IDLE_TIMEOUT, + SHRPX_OPTID_FRONTEND_QUIC_QLOG_DIR, SHRPX_OPTID_FRONTEND_READ_TIMEOUT, SHRPX_OPTID_FRONTEND_WRITE_TIMEOUT, SHRPX_OPTID_HEADER_FIELD_BUFFER, diff --git a/src/shrpx_http3_upstream.cc b/src/shrpx_http3_upstream.cc index 762a5a69..098bc1b2 100644 --- a/src/shrpx_http3_upstream.cc +++ b/src/shrpx_http3_upstream.cc @@ -24,7 +24,11 @@ */ #include "shrpx_http3_upstream.h" -#include +#include +#include +#include + +#include #include @@ -112,6 +116,7 @@ size_t downstream_queue_size(Worker *worker) { Http3Upstream::Http3Upstream(ClientHandler *handler) : handler_{handler}, + qlog_fd_{-1}, conn_{nullptr}, tls_alert_{0}, httpconn_{nullptr}, @@ -149,6 +154,10 @@ Http3Upstream::~Http3Upstream() { if (conn_) { ngtcp2_conn_del(conn_); } + + if (qlog_fd_ != -1) { + close(qlog_fd_); + } } namespace { @@ -171,6 +180,29 @@ void log_printf(void *user_data, const char *fmt, ...) { } } // namespace +namespace { +void qlog_write(void *user_data, uint32_t flags, const void *data, + size_t datalen) { + auto upstream = static_cast(user_data); + + upstream->qlog_write(data, datalen, flags & NGTCP2_QLOG_WRITE_FLAG_FIN); +} +} // namespace + +void Http3Upstream::qlog_write(const void *data, size_t datalen, bool fin) { + assert(qlog_fd_ != -1); + + ssize_t nwrite; + + while ((nwrite = write(qlog_fd_, data, datalen)) == -1 && errno == EINTR) + ; + + if (fin) { + close(qlog_fd_); + qlog_fd_ = -1; + } +} + namespace { void rand(uint8_t *dest, size_t destlen, const ngtcp2_rand_ctx *rand_ctx) { util::random_bytes(dest, dest + destlen, @@ -526,6 +558,16 @@ int Http3Upstream::init(const UpstreamAddr *faddr, const Address &remote_addr, if (quicconf.upstream.debug.log) { settings.log_printf = log_printf; } + + if (!quicconf.upstream.qlog.dir.empty()) { + auto fd = open_qlog_file(quicconf.upstream.qlog.dir, scid); + if (fd != -1) { + qlog_fd_ = fd; + settings.qlog.odcid = initial_hd.dcid; + settings.qlog.write = shrpx::qlog_write; + } + } + settings.initial_ts = quic_timestamp(); settings.cc_algo = NGTCP2_CC_ALGO_BBR; settings.max_window = http3conf.upstream.max_connection_window_size; @@ -2526,4 +2568,44 @@ int Http3Upstream::submit_goaway() { void Http3Upstream::idle_close() { idle_close_ = true; } +int Http3Upstream::open_qlog_file(const StringRef &dir, + const ngtcp2_cid &scid) const { + std::array buf; + + auto path = dir.str(); + path += '/'; + path += + util::format_iso8601_basic(buf.data(), std::chrono::system_clock::now()); + path += '-'; + path += util::format_hex(scid.data, scid.datalen); + path += ".qlog"; + + int fd; + +#ifdef O_CLOEXEC + while ((fd = open(path.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_CLOEXEC, + S_IRUSR | S_IWUSR | S_IRGRP)) == -1 && + errno == EINTR) + ; +#else // !O_CLOEXEC + while ((fd = open(path.c_str(), O_WRONLY | O_CREAT | O_TRUNC, + S_IRUSR | S_IWUSR | S_IRGRP)) == -1 && + errno == EINTR) + ; + + if (fd != -1) { + util::make_socket_closeonexec(fd); + } +#endif // !O_CLOEXEC + + if (fd == -1) { + auto error = errno; + ULOG(ERROR, this) << "Failed to open qlog file " << path + << ": errno=" << error; + return -1; + } + + return fd; +} + } // namespace shrpx diff --git a/src/shrpx_http3_upstream.h b/src/shrpx_http3_upstream.h index db907eee..845abe92 100644 --- a/src/shrpx_http3_upstream.h +++ b/src/shrpx_http3_upstream.h @@ -149,12 +149,16 @@ public: int submit_goaway(); void idle_close(); + void qlog_write(const void *data, size_t datalen, bool fin); + int open_qlog_file(const StringRef &dir, const ngtcp2_cid &scid) const; + private: ClientHandler *handler_; ev_timer timer_; ev_timer idle_timer_; ev_timer shutdown_timer_; ev_prepare prep_; + int qlog_fd_; ngtcp2_conn *conn_; quic::Error last_error_; uint8_t tls_alert_; diff --git a/src/util.cc b/src/util.cc index 7bc94513..6efc0e9e 100644 --- a/src/util.cc +++ b/src/util.cc @@ -396,6 +396,47 @@ char *iso8601_date(char *res, int64_t ms) { return p; } +char *iso8601_basic_date(char *res, int64_t ms) { + time_t sec = ms / 1000; + + tm tms; + if (localtime_r(&sec, &tms) == nullptr) { + return res; + } + + auto p = res; + + p = cpydig(p, tms.tm_year + 1900, 4); + p = cpydig(p, tms.tm_mon + 1, 2); + p = cpydig(p, tms.tm_mday, 2); + *p++ = 'T'; + p = cpydig(p, tms.tm_hour, 2); + p = cpydig(p, tms.tm_min, 2); + p = cpydig(p, tms.tm_sec, 2); + *p++ = '.'; + p = cpydig(p, ms % 1000, 3); + +#ifdef HAVE_STRUCT_TM_TM_GMTOFF + auto gmtoff = tms.tm_gmtoff; +#else // !HAVE_STRUCT_TM_TM_GMTOFF + auto gmtoff = nghttp2_timegm(&tms) - sec; +#endif // !HAVE_STRUCT_TM_TM_GMTOFF + if (gmtoff == 0) { + *p++ = 'Z'; + } else { + if (gmtoff > 0) { + *p++ = '+'; + } else { + *p++ = '-'; + gmtoff = -gmtoff; + } + p = cpydig(p, gmtoff / 3600, 2); + p = cpydig(p, (gmtoff % 3600) / 60, 2); + } + + return p; +} + #ifdef _WIN32 namespace bt = boost::posix_time; // one-time definition of the locale that is used to parse UTC strings diff --git a/src/util.h b/src/util.h index 16c26ff1..ca9b437d 100644 --- a/src/util.h +++ b/src/util.h @@ -247,6 +247,11 @@ std::string iso8601_date(int64_t ms); // function returns the one beyond the last position. char *iso8601_date(char *res, int64_t ms); +// Writes given time |t| from epoch in ISO 8601 basic format into the +// buffer pointed by |res|. The buffer must be at least 24 bytes +// long. This function returns the one beyond the last position. +char *iso8601_basic_date(char *res, int64_t ms); + time_t parse_http_date(const StringRef &s); // Parses time formatted as "MMM DD HH:MM:SS YYYY [GMT]" (e.g., Feb 3 @@ -657,6 +662,20 @@ template StringRef format_iso8601(char *out, const T &tp) { return StringRef{out, p}; } +// Writes given time |tp| in ISO 8601 basic format (e.g., +// 20141115T125824.741Z or 20141115T125824.741+0900) in buffer pointed +// by |out|. The buffer must be at least 25 bytes, including terminal +// NULL byte. Expected type of |tp| is std::chrono::time_point. This +// function returns StringRef wrapping the buffer pointed by |out|, +// and this string is terminated by NULL. +template StringRef format_iso8601_basic(char *out, const T &tp) { + auto t = std::chrono::duration_cast( + tp.time_since_epoch()); + auto p = iso8601_basic_date(out, t.count()); + *p = '\0'; + return StringRef{out, p}; +} + // Writes given time |tp| in HTTP Date format (e.g., Mon, 10 Oct 2016 // 10:25:58 GMT) in buffer pointed by |out|. The buffer must be at // least 30 bytes, including terminal NULL byte. Expected type of