nghttpx: Add qlog support

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 = [

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=<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=<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;
       }

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";

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,

src/shrpx_http3_upstream.cc

@@ -24,7 +24,11 @@
  */
 #include "shrpx_http3_upstream.h"
 
-#include <stdio.h>
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+
+#include <cstdio>
 
 #include <ngtcp2/ngtcp2_crypto.h>
 
@@ -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<Http3Upstream *>(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<char, sizeof("20141115T125824.741+0900")> 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

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_;

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

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 <typename T> 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 <typename T> StringRef format_iso8601_basic(char *out, const T &tp) {
+  auto t = std::chrono::duration_cast<std::chrono::milliseconds>(
+      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