nghttpx: Log non-final response headers

src/shrpx_http2_session.cc

@@ -921,11 +921,20 @@ int on_response_headers(Http2Session *http2session,
   downstream->set_response_major(2);
   downstream->set_response_minor(0);
 
+  if(LOG_ENABLED(INFO)) {
+    std::stringstream ss;
+    for(auto& nv : nva) {
+      ss << TTY_HTTP_HD << nv.name << TTY_RST << ": " << nv.value << "\n";
+    }
+    SSLOG(INFO, http2session) << "HTTP response headers. stream_id="
+                              << frame->hd.stream_id
+                              << "\n" << ss.str();
+  }
+
   if(downstream->get_non_final_response()) {
 
     if(LOG_ENABLED(INFO)) {
-      SSLOG(INFO, http2session) << "HTTP non-final response. stream_id="
+      SSLOG(INFO, http2session) << "This is non-final response.";
-                                << frame->hd.stream_id;
     }
 
     downstream->set_expect_final_response(true);
@@ -944,16 +953,6 @@ int on_response_headers(Http2Session *http2session,
 
   downstream->set_expect_final_response(false);
 
-  if(LOG_ENABLED(INFO)) {
-    std::stringstream ss;
-    for(auto& nv : nva) {
-      ss << TTY_HTTP_HD << nv.name << TTY_RST << ": " << nv.value << "\n";
-    }
-    SSLOG(INFO, http2session) << "HTTP response headers. stream_id="
-                              << frame->hd.stream_id
-                              << "\n" << ss.str();
-  }
-
   auto content_length = http2::get_header(nva, "content-length");
   if(!content_length && downstream->get_request_method() != "HEAD" &&
      downstream->get_request_method() != "CONNECT") {

src/shrpx_http2_upstream.cc

@@ -1163,6 +1163,10 @@ int Http2Upstream::on_downstream_header_complete(Downstream *downstream)
   http2::copy_norm_headers_to_nva(nva, downstream->get_response_headers());
 
   if(downstream->get_non_final_response()) {
+    if(LOG_ENABLED(INFO)) {
+      log_response_headers(downstream, nva);
+    }
+
     rv = nghttp2_submit_headers(session_, NGHTTP2_FLAG_NONE,
                                 downstream->get_stream_id(), nullptr,
                                 nva.data(), nva.size(), nullptr);
@@ -1197,17 +1201,7 @@ int Http2Upstream::on_downstream_header_complete(Downstream *downstream)
   }
 
   if(LOG_ENABLED(INFO)) {
-    std::stringstream ss;
+    log_response_headers(downstream, nva);
-    for(auto& nv : nva) {
-      ss << TTY_HTTP_HD;
-      ss.write(reinterpret_cast<const char*>(nv.name), nv.namelen);
-      ss << TTY_RST << ": ";
-      ss.write(reinterpret_cast<const char*>(nv.value), nv.valuelen);
-      ss << "\n";
-    }
-    ULOG(INFO, this) << "HTTP response headers. stream_id="
-                     << downstream->get_stream_id() << "\n"
-                     << ss.str();
   }
 
   if(get_config()->http2_upstream_dump_response_header) {
@@ -1334,4 +1328,20 @@ int Http2Upstream::consume(int32_t stream_id, size_t len)
   return 0;
 }
 
+void Http2Upstream::log_response_headers
+(Downstream *downstream, const std::vector<nghttp2_nv>& nva) const
+{
+  std::stringstream ss;
+  for(auto& nv : nva) {
+    ss << TTY_HTTP_HD;
+    ss.write(reinterpret_cast<const char*>(nv.name), nv.namelen);
+    ss << TTY_RST << ": ";
+    ss.write(reinterpret_cast<const char*>(nv.value), nv.valuelen);
+    ss << "\n";
+  }
+  ULOG(INFO, this) << "HTTP response headers. stream_id="
+                   << downstream->get_stream_id() << "\n"
+                   << ss.str();
+}
+
 } // namespace shrpx

src/shrpx_http2_upstream.h

@@ -79,6 +79,8 @@ public:
   int start_settings_timer();
   void stop_settings_timer();
   int consume(int32_t stream_id, size_t len);
+  void log_response_headers(Downstream *downstream,
+                            const std::vector<nghttp2_nv>& nva) const;
 private:
   DownstreamQueue downstream_queue_;
   std::unique_ptr<HttpsUpstream> pre_upstream_;

src/shrpx_https_upstream.cc

@@ -776,6 +776,10 @@ int HttpsUpstream::on_downstream_header_complete(Downstream *downstream)
   if(downstream->get_non_final_response()) {
     hdrs += "\r\n";
 
+    if(LOG_ENABLED(INFO)) {
+      log_response_headers(hdrs);
+    }
+
     auto output = bufferevent_get_output(handler_->get_bev());
     if(evbuffer_add(output, hdrs.c_str(), hdrs.size()) != 0) {
       ULOG(FATAL, this) << "evbuffer_add() failed";
@@ -846,17 +850,11 @@ int HttpsUpstream::on_downstream_header_complete(Downstream *downstream)
   }
 
   hdrs += "\r\n";
+
   if(LOG_ENABLED(INFO)) {
-    const char *hdrp;
+    log_response_headers(hdrs);
-    std::string nhdrs;
-    if(worker_config.errorlog_tty) {
-      nhdrs = http::colorizeHeaders(hdrs.c_str());
-      hdrp = nhdrs.c_str();
-    } else {
-      hdrp = hdrs.c_str();
-    }
-    ULOG(INFO, this) << "HTTP response headers\n" << hdrp;
   }
+
   auto output = bufferevent_get_output(handler_->get_bev());
   if(evbuffer_add(output, hdrs.c_str(), hdrs.size()) != 0) {
     ULOG(FATAL, this) << "evbuffer_add() failed";
@@ -939,4 +937,17 @@ int HttpsUpstream::on_downstream_abort_request(Downstream *downstream,
   return error_reply(status_code);
 }
 
+void HttpsUpstream::log_response_headers(const std::string& hdrs) const
+{
+  const char *hdrp;
+  std::string nhdrs;
+  if(worker_config.errorlog_tty) {
+    nhdrs = http::colorizeHeaders(hdrs.c_str());
+    hdrp = nhdrs.c_str();
+  } else {
+    hdrp = hdrs.c_str();
+  }
+  ULOG(INFO, this) << "HTTP response headers\n" << hdrp;
+}
+
 } // namespace shrpx

src/shrpx_https_upstream.h

@@ -65,6 +65,7 @@ public:
   virtual int on_downstream_body_complete(Downstream *downstream);
 
   void reset_current_header_length();
+  void log_response_headers(const std::string& hdrs) const;
 private:
   ClientHandler *handler_;
   http_parser htp_;