nghttpx: Add --frontend-frame-debug option to debug HTTP/2 frame in upstream

The output format is the same one with nghttp/nghttpd. The output
is made into stderr to make it sync with logging.

src/Makefile.am

@@ -71,6 +71,7 @@ nghttpd_SOURCES = ${HELPER_OBJECTS} ${HELPER_HFILES} nghttpd.cc \
 
 NGHTTPX_SRCS = \
 	util.cc util.h http2.cc http2.h timegm.c timegm.h base64.h \
+	app_helper.cc app_helper.h \
 	shrpx_config.cc shrpx_config.h \
 	shrpx_error.h \
 	shrpx_listen_handler.cc shrpx_listen_handler.h \

src/app_helper.cc

@@ -132,20 +132,29 @@ const char* strframetype(uint8_t type)
 } // namespace
 
 namespace {
-void print_frame_attr_indent()
+bool color_output = false;
+} // namespace
+
+void set_color_output(bool f)
 {
-  printf("          ");
+  color_output = f;
 }
-} // namespace
 
 namespace {
-bool color_output = false;
+FILE *outfile = stdout;
 } // namespace
 
-void set_color_output(bool f)
+void set_output(FILE *file)
 {
-  color_output = f;
+  outfile = file;
+}
+
+namespace {
+void print_frame_attr_indent()
+{
+  fprintf(outfile, "          ");
 }
+} // namespace
 
 namespace {
 const char* ansi_esc(const char *code)
@@ -168,11 +177,11 @@ void print_nv(nghttp2_nv *nva, size_t nvlen, bool indent = true)
     if(indent) {
       print_frame_attr_indent();
     }
-    printf("%s", ansi_esc("\033[1;34m"));
-    fwrite(nv.name, nv.namelen, 1, stdout);
-    printf("%s: ", ansi_escend());
-    fwrite(nv.value, nv.valuelen, 1, stdout);
-    printf("\n");
+    fprintf(outfile, "%s", ansi_esc("\033[1;34m"));
+    fwrite(nv.name, nv.namelen, 1, outfile);
+    fprintf(outfile, "%s: ", ansi_escend());
+    fwrite(nv.value, nv.valuelen, 1, outfile);
+    fprintf(outfile, "\n");
   }
 }
 } // namelen
@@ -180,17 +189,17 @@ void print_nv(nghttp2_nv *nva, size_t nvlen, bool indent = true)
 void print_timer()
 {
   auto millis = get_timer();
-  printf("%s[%3ld.%03ld]%s",
-         ansi_esc("\033[33m"),
-         (long int)(millis.count()/1000), (long int)(millis.count()%1000),
-         ansi_escend());
+  fprintf(outfile, "%s[%3ld.%03ld]%s",
+          ansi_esc("\033[33m"),
+          (long int)(millis.count()/1000), (long int)(millis.count()%1000),
+          ansi_escend());
 }
 
 namespace {
 void print_frame_hd(const nghttp2_frame_hd& hd)
 {
-  printf("<length=%zu, flags=0x%02x, stream_id=%d>\n",
-         hd.length, hd.flags, hd.stream_id);
+  fprintf(outfile, "<length=%zu, flags=0x%02x, stream_id=%d>\n",
+          hd.length, hd.flags, hd.stream_id);
 }
 } // namespace
 
@@ -285,7 +294,7 @@ void print_flags(const nghttp2_frame_hd& hd)
     }
     break;
   }
-  printf("; %s\n", s.c_str());
+  fprintf(outfile, "; %s\n", s.c_str());
 }
 } // namespace
 
@@ -304,10 +313,10 @@ const char* frame_name_ansi_esc(print_type ptype)
 namespace {
 void print_frame(print_type ptype, const nghttp2_frame *frame)
 {
-  printf("%s%s%s frame ",
-         frame_name_ansi_esc(ptype),
-         strframetype(frame->hd.type),
-         ansi_escend());
+  fprintf(outfile, "%s%s%s frame ",
+          frame_name_ansi_esc(ptype),
+          strframetype(frame->hd.type),
+          ansi_escend());
   print_frame_hd(frame->hd);
   if(frame->hd.flags) {
     print_frame_attr_indent();
@@ -317,25 +326,25 @@ void print_frame(print_type ptype, const nghttp2_frame *frame)
   case NGHTTP2_DATA:
     if(frame->hd.flags & (NGHTTP2_FLAG_PAD_HIGH | NGHTTP2_FLAG_PAD_LOW)) {
       print_frame_attr_indent();
-      printf("(padlen=%zu)\n", frame->data.padlen);
+      fprintf(outfile, "(padlen=%zu)\n", frame->data.padlen);
     }
     break;
   case NGHTTP2_HEADERS:
     print_frame_attr_indent();
-    printf("(pri=%d, padlen=%zu)\n",
-           frame->headers.pri, frame->headers.padlen);
+    fprintf(outfile, "(pri=%d, padlen=%zu)\n",
+            frame->headers.pri, frame->headers.padlen);
     switch(frame->headers.cat) {
     case NGHTTP2_HCAT_REQUEST:
       print_frame_attr_indent();
-      printf("; Open new stream\n");
+      fprintf(outfile, "; Open new stream\n");
       break;
     case NGHTTP2_HCAT_RESPONSE:
       print_frame_attr_indent();
-      printf("; First response header\n");
+      fprintf(outfile, "; First response header\n");
       break;
     case NGHTTP2_HCAT_PUSH_RESPONSE:
       print_frame_attr_indent();
-      printf("; First push response header\n");
+      fprintf(outfile, "; First push response header\n");
       break;
     default:
       break;
@@ -344,54 +353,56 @@ void print_frame(print_type ptype, const nghttp2_frame *frame)
     break;
   case NGHTTP2_PRIORITY:
     print_frame_attr_indent();
-    printf("(pri=%d)\n", frame->priority.pri);
+    fprintf(outfile, "(pri=%d)\n", frame->priority.pri);
     break;
   case NGHTTP2_RST_STREAM:
     print_frame_attr_indent();
-    printf("(error_code=%s(%u))\n",
-           strstatus(frame->rst_stream.error_code),
-           frame->rst_stream.error_code);
+    fprintf(outfile, "(error_code=%s(%u))\n",
+            strstatus(frame->rst_stream.error_code),
+            frame->rst_stream.error_code);
     break;
   case NGHTTP2_SETTINGS:
     print_frame_attr_indent();
-    printf("(niv=%lu)\n", static_cast<unsigned long>(frame->settings.niv));
+    fprintf(outfile, "(niv=%lu)\n",
+            static_cast<unsigned long>(frame->settings.niv));
     for(size_t i = 0; i < frame->settings.niv; ++i) {
       print_frame_attr_indent();
-      printf("[%s(%d):%u]\n",
-             strsettingsid(frame->settings.iv[i].settings_id),
-             frame->settings.iv[i].settings_id,
-             frame->settings.iv[i].value);
+      fprintf(outfile, "[%s(%d):%u]\n",
+              strsettingsid(frame->settings.iv[i].settings_id),
+              frame->settings.iv[i].settings_id,
+              frame->settings.iv[i].value);
     }
     break;
   case NGHTTP2_PUSH_PROMISE:
     print_frame_attr_indent();
-    printf("(promised_stream_id=%d, padlen=%zu)\n",
-           frame->push_promise.promised_stream_id,
-           frame->push_promise.padlen);
+    fprintf(outfile, "(promised_stream_id=%d, padlen=%zu)\n",
+            frame->push_promise.promised_stream_id,
+            frame->push_promise.padlen);
     print_nv(frame->push_promise.nva, frame->push_promise.nvlen);
     break;
   case NGHTTP2_PING:
     print_frame_attr_indent();
-    printf("(opaque_data=%s)\n",
-           util::format_hex(frame->ping.opaque_data, 8).c_str());
+    fprintf(outfile, "(opaque_data=%s)\n",
+            util::format_hex(frame->ping.opaque_data, 8).c_str());
     break;
   case NGHTTP2_GOAWAY:
     print_frame_attr_indent();
-    printf("(last_stream_id=%d, error_code=%s(%u), opaque_data(%u)=[%s])\n",
-           frame->goaway.last_stream_id,
-           strstatus(frame->goaway.error_code),
-           frame->goaway.error_code,
-           static_cast<unsigned int>(frame->goaway.opaque_data_len),
-           util::format_hex(frame->goaway.opaque_data,
-                            frame->goaway.opaque_data_len).c_str());
+    fprintf(outfile,
+            "(last_stream_id=%d, error_code=%s(%u), opaque_data(%u)=[%s])\n",
+            frame->goaway.last_stream_id,
+            strstatus(frame->goaway.error_code),
+            frame->goaway.error_code,
+            static_cast<unsigned int>(frame->goaway.opaque_data_len),
+            util::format_hex(frame->goaway.opaque_data,
+                             frame->goaway.opaque_data_len).c_str());
     break;
   case NGHTTP2_WINDOW_UPDATE:
     print_frame_attr_indent();
-    printf("(window_size_increment=%d)\n",
-           frame->window_update.window_size_increment);
+    fprintf(outfile, "(window_size_increment=%d)\n",
+            frame->window_update.window_size_increment);
     break;
   default:
-    printf("\n");
+    fprintf(outfile, "\n");
     break;
   }
 }
@@ -408,7 +419,7 @@ int verbose_on_header_callback(nghttp2_session *session,
     static_cast<uint16_t>(namelen), static_cast<uint16_t>(valuelen)
   };
   print_timer();
-  printf(" (stream_id=%d) ", frame->hd.stream_id);
+  fprintf(outfile, " (stream_id=%d) ", frame->hd.stream_id);
   print_nv(&nv, 1, false /* no indent */);
   return 0;
 }
@@ -417,9 +428,9 @@ int verbose_on_frame_recv_callback
 (nghttp2_session *session, const nghttp2_frame *frame, void *user_data)
 {
   print_timer();
-  printf(" recv ");
+  fprintf(outfile, " recv ");
   print_frame(PRINT_RECV, frame);
-  fflush(stdout);
+  fflush(outfile);
   return 0;
 }
 
@@ -428,9 +439,9 @@ int verbose_on_invalid_frame_recv_callback
  nghttp2_error_code error_code, void *user_data)
 {
   print_timer();
-  printf(" [INVALID; status=%s] recv ", strstatus(error_code));
+  fprintf(outfile, " [INVALID; status=%s] recv ", strstatus(error_code));
   print_frame(PRINT_RECV, frame);
-  fflush(stdout);
+  fflush(outfile);
   return 0;
 }
 
@@ -439,11 +450,11 @@ void dump_header(const uint8_t *head, size_t headlen)
 {
   size_t i;
   print_frame_attr_indent();
-  printf("Header dump: ");
+  fprintf(outfile, "Header dump: ");
   for(i = 0; i < headlen; ++i) {
-    printf("%02X ", head[i]);
+    fprintf(outfile, "%02X ", head[i]);
   }
-  printf("\n");
+  fprintf(outfile, "\n");
 }
 } // namespace
 
@@ -455,9 +466,9 @@ int verbose_on_unknown_frame_recv_callback(nghttp2_session *session,
                                            void *user_data)
 {
   print_timer();
-  printf(" recv unknown frame\n");
+  fprintf(outfile, " recv unknown frame\n");
   dump_header(head, headlen);
-  fflush(stdout);
+  fflush(outfile);
   return 0;
 }
 
@@ -465,9 +476,9 @@ int verbose_on_frame_send_callback
 (nghttp2_session *session, const nghttp2_frame *frame, void *user_data)
 {
   print_timer();
-  printf(" send ");
+  fprintf(outfile, " send ");
   print_frame(PRINT_SEND, frame);
-  fflush(stdout);
+  fflush(outfile);
   return 0;
 }
 

src/app_helper.h

@@ -86,6 +86,10 @@ void print_timer();
 // variable.
 void set_color_output(bool f);
 
+// Set output file when printing HTTP2 frames. By default, stdout is
+// used.
+void set_output(FILE *file);
+
 } // namespace nghttp2
 
 #endif // APP_HELPER_H

src/shrpx.cc

@@ -53,6 +53,7 @@
 #include "shrpx_listen_handler.h"
 #include "shrpx_ssl.h"
 #include "util.h"
+#include "app_helper.h"
 
 using namespace nghttp2;
 
@@ -435,6 +436,7 @@ void fill_default_config()
   mod_config()->http2_upstream_dump_request_header = nullptr;
   mod_config()->http2_upstream_dump_response_header = nullptr;
   mod_config()->http2_no_cookie_crumbling = false;
+  mod_config()->upstream_frame_debug = false;
 }
 } // namespace
 
@@ -736,6 +738,10 @@ void print_help(std::ostream& out)
       << "                       an empty line.\n"
       << "                       This option is not thread safe and MUST NOT\n"
       << "                       be used with option -n=N, where N >= 2.\n"
+      << "    -o, --frontend-frame-debug\n"
+      << "                       Print HTTP/2 frames in frontend to stderr.\n"
+      << "                       This option is not thread safe and MUST NOT\n"
+      << "                       be used with option -n=N, where N >= 2.\n"
       << "    -D, --daemon       Run in a background. If -D is used, the\n"
       << "                       current working directory is changed to '/'.\n"
       << "    --pid-file=<PATH>  Set path to save PID of this program.\n"
@@ -771,6 +777,7 @@ int main(int argc, char **argv)
       {"client-proxy", no_argument, nullptr, 'p'},
       {"http2-proxy", no_argument, nullptr, 's'},
       {"version", no_argument, nullptr, 'v'},
+      {"frontend-frame-debug", no_argument, nullptr, 'o'},
       {"add-x-forwarded-for", no_argument, &flag, 1},
       {"frontend-http2-read-timeout", required_argument, &flag, 2},
       {"frontend-read-timeout", required_argument, &flag, 3},
@@ -821,7 +828,7 @@ int main(int argc, char **argv)
     };
 
     int option_index = 0;
-    int c = getopt_long(argc, argv, "DL:b:c:f:hkn:psv", long_options,
+    int c = getopt_long(argc, argv, "DL:b:c:f:hkn:opsv", long_options,
                         &option_index);
     if(c == -1) {
       break;
@@ -851,6 +858,9 @@ int main(int argc, char **argv)
     case 'n':
       cmdcfgs.emplace_back(SHRPX_OPT_WORKERS, optarg);
       break;
+    case 'o':
+      cmdcfgs.emplace_back(SHRPX_OPT_FRONTEND_FRAME_DEBUG, "yes");
+      break;
     case 'p':
       cmdcfgs.emplace_back(SHRPX_OPT_CLIENT_PROXY, "yes");
       break;
@@ -1204,6 +1214,15 @@ int main(int argc, char **argv)
      get_rate_limit(get_config()->write_burst),
      nullptr);
 
+  if(get_config()->upstream_frame_debug) {
+    // To make it sync to logging
+    set_output(stderr);
+    if(isatty(fileno(stdout))) {
+      set_color_output(true);
+    }
+    reset_timer();
+  }
+
   struct sigaction act;
   memset(&act, 0, sizeof(struct sigaction));
   act.sa_handler = SIG_IGN;

src/shrpx_config.cc

@@ -115,6 +115,7 @@ const char SHRPX_OPT_FRONTEND_HTTP2_DUMP_REQUEST_HEADER[] =
 const char SHRPX_OPT_FRONTEND_HTTP2_DUMP_RESPONSE_HEADER[] =
   "frontend-http2-dump-response-header";
 const char SHRPX_OPT_HTTP2_NO_COOKIE_CRUMBLING[] = "http2-no-cookie-crumbling";
+const char SHRPX_OPT_FRONTEND_FRAME_DEBUG[] = "frontend-frame-debug";
 
 namespace {
 Config *config = nullptr;
@@ -480,6 +481,8 @@ int parse_config(const char *opt, const char *optarg)
     mod_config()->http2_upstream_dump_response_header = f;
   } else if(util::strieq(opt, SHRPX_OPT_HTTP2_NO_COOKIE_CRUMBLING)) {
     mod_config()->http2_no_cookie_crumbling = util::strieq(optarg, "yes");
+  } else if(util::strieq(opt, SHRPX_OPT_FRONTEND_FRAME_DEBUG)) {
+    mod_config()->upstream_frame_debug = util::strieq(optarg, "yes");
   } else if(util::strieq(opt, "conf")) {
     LOG(WARNING) << "conf is ignored";
   } else {

src/shrpx_config.h

@@ -102,6 +102,7 @@ extern const char SHRPX_OPT_CLIENT_CERT_FILE[];
 extern const char SHRPX_OPT_FRONTEND_HTTP2_DUMP_REQUEST_HEADER[];
 extern const char SHRPX_OPT_FRONTEND_HTTP2_DUMP_RESPONSE_HEADER[];
 extern const char SHRPX_OPT_HTTP2_NO_COOKIE_CRUMBLING[];
+extern const char SHRPX_OPT_FRONTEND_FRAME_DEBUG[];
 
 union sockaddr_union {
   sockaddr sa;
@@ -213,6 +214,7 @@ struct Config {
   // true if stderr refers to a terminal.
   bool tty;
   bool http2_no_cookie_crumbling;
+  bool upstream_frame_debug;
 };
 
 const Config* get_config();

src/shrpx_http2_upstream.cc

@@ -39,6 +39,7 @@
 #include "http2.h"
 #include "util.h"
 #include "base64.h"
+#include "app_helper.h"
 
 using namespace nghttp2;
 
@@ -205,6 +206,10 @@ int on_header_callback(nghttp2_session *session,
                        const uint8_t *value, size_t valuelen,
                        void *user_data)
 {
+  if(get_config()->upstream_frame_debug) {
+    verbose_on_header_callback(session, frame, name, namelen, value, valuelen,
+                               user_data);
+  }
   if(frame->hd.type != NGHTTP2_HEADERS ||
      frame->headers.cat != NGHTTP2_HCAT_REQUEST) {
     return 0;
@@ -359,6 +364,9 @@ int on_frame_recv_callback
 (nghttp2_session *session, const nghttp2_frame *frame, void *user_data)
 {
   int rv;
+  if(get_config()->upstream_frame_debug) {
+    verbose_on_frame_recv_callback(session, frame, user_data);
+  }
   auto upstream = static_cast<Http2Upstream*>(user_data);
   switch(frame->hd.type) {
   case NGHTTP2_DATA: {
@@ -428,6 +436,9 @@ namespace {
 int on_frame_send_callback(nghttp2_session* session,
                            const nghttp2_frame *frame, void *user_data)
 {
+  if(get_config()->upstream_frame_debug) {
+    verbose_on_frame_send_callback(session, frame, user_data);
+  }
   auto upstream = static_cast<Http2Upstream*>(user_data);
   if(frame->hd.type == NGHTTP2_SETTINGS &&
      (frame->hd.flags & NGHTTP2_FLAG_ACK) == 0) {