Make hpack tracing available in opt builds also (#27728)

src/core/ext/transport/chttp2/transport/hpack_parser.cc

@@ -51,7 +51,7 @@
 
 namespace grpc_core {
 
-DebugOnlyTraceFlag grpc_trace_chttp2_hpack_parser(false, "chttp2_hpack_parser");
+TraceFlag grpc_trace_chttp2_hpack_parser(false, "chttp2_hpack_parser");
 
 /* state table for huffman decoding: given a state, gives an index/16 into
    next_sub_tbl. Taking that index and adding the value of the nibble being
@@ -940,13 +940,15 @@ class HPackParser::Parser {
  public:
   Parser(Input* input, grpc_metadata_batch* metadata_buffer,
          uint32_t metadata_size_limit, HPackTable* table,
-         uint8_t* dynamic_table_updates_allowed, uint32_t* frame_length)
+         uint8_t* dynamic_table_updates_allowed, uint32_t* frame_length,
+         LogInfo log_info)
       : input_(input),
         metadata_buffer_(metadata_buffer),
         table_(table),
         dynamic_table_updates_allowed_(dynamic_table_updates_allowed),
         frame_length_(frame_length),
-        metadata_size_limit_(metadata_size_limit) {}
+        metadata_size_limit_(metadata_size_limit),
+        log_info_(log_info) {}
 
   // Skip any priority bits, or return false on failure
   bool SkipPriority() {
@@ -1058,8 +1060,20 @@ class HPackParser::Parser {
 
  private:
   void GPR_ATTRIBUTE_NOINLINE LogHeader(const HPackTable::Memento& memento) {
-    // TODO(ctiller): what should be here?
+    const char* type;
-    gpr_log(GPR_DEBUG, "recvhdr: %s", memento.DebugString().c_str());
+    switch (log_info_.type) {
+      case LogInfo::kHeaders:
+        type = "HDR";
+        break;
+      case LogInfo::kTrailers:
+        type = "TRL";
+        break;
+      case LogInfo::kDontKnow:
+        type = "???";
+        break;
+    }
+    gpr_log(GPR_DEBUG, "HTTP:%d:%s:%s: %s", log_info_.stream_id, type,
+            log_info_.is_client ? "CLI" : "SVR", memento.DebugString().c_str());
   }
 
   bool EmitHeader(const HPackTable::Memento& md) {
@@ -1179,9 +1193,6 @@ class HPackParser::Parser {
           false);
     }
     (*dynamic_table_updates_allowed_)--;
-    if (GRPC_TRACE_FLAG_ENABLED(grpc_trace_chttp2_hpack_parser)) {
-      gpr_log(GPR_INFO, "MAX TABLE SIZE: %d", *size);
-    }
     grpc_error_handle err = table_->SetCurrentTableSize(*size);
     if (err != GRPC_ERROR_NONE) {
       input_->SetError(err);
@@ -1224,12 +1235,13 @@ class HPackParser::Parser {
         false);
   }
 
-  Input* input_;
+  Input* const input_;
-  grpc_metadata_batch* metadata_buffer_;
+  grpc_metadata_batch* const metadata_buffer_;
   HPackTable* const table_;
   uint8_t* const dynamic_table_updates_allowed_;
   uint32_t* const frame_length_;
-  uint32_t metadata_size_limit_;
+  const uint32_t metadata_size_limit_;
+  const LogInfo log_info_;
 };
 
 UnmanagedMemorySlice HPackParser::String::Take(Extern) {
@@ -1284,13 +1296,14 @@ HPackParser::~HPackParser() = default;
 
 void HPackParser::BeginFrame(grpc_metadata_batch* metadata_buffer,
                              uint32_t metadata_size_limit, Boundary boundary,
-                             Priority priority) {
+                             Priority priority, LogInfo log_info) {
   metadata_buffer_ = metadata_buffer;
   boundary_ = boundary;
   priority_ = priority;
   dynamic_table_updates_allowed_ = 2;
   frame_length_ = 0;
   metadata_size_limit_ = metadata_size_limit;
+  log_info_ = log_info;
 }
 
 grpc_error_handle HPackParser::Parse(const grpc_slice& slice, bool is_last) {
@@ -1335,7 +1348,7 @@ bool HPackParser::ParseInputInner(Input* input) {
   while (!input->end_of_stream()) {
     if (GPR_UNLIKELY(!Parser(input, metadata_buffer_, metadata_size_limit_,
                              &table_, &dynamic_table_updates_allowed_,
-                             &frame_length_)
+                             &frame_length_, log_info_)
                           .Parse())) {
       return false;
     }

src/core/ext/transport/chttp2/transport/hpack_parser.h

@@ -49,6 +49,20 @@ class HPackParser {
     // Yes there's a priority field
     Included
   };
+  // Details about a frame we only need to know for logging
+  struct LogInfo {
+    // The stream ID
+    uint32_t stream_id;
+    // Headers or trailers?
+    enum Type : uint8_t {
+      kHeaders,
+      kTrailers,
+      kDontKnow,
+    };
+    Type type;
+    // Client or server?
+    bool is_client;
+  };
 
   HPackParser();
   ~HPackParser();
@@ -61,7 +75,7 @@ class HPackParser {
   // Sink receives each parsed header,
   void BeginFrame(grpc_metadata_batch* metadata_buffer,
                   uint32_t metadata_size_limit, Boundary boundary,
-                  Priority priority);
+                  Priority priority, LogInfo log_info);
   // Start throwing away any received headers after parsing them.
   void StopBufferingFrame() { metadata_buffer_ = nullptr; }
   // Parse one slice worth of data
@@ -102,6 +116,8 @@ class HPackParser {
   // Length of frame so far.
   uint32_t frame_length_;
   uint32_t metadata_size_limit_;
+  // Information for logging
+  LogInfo log_info_;
 
   // hpack table
   HPackTable table_;

src/core/ext/transport/chttp2/transport/parsing.cc

@@ -324,6 +324,15 @@ static HPackParser::Boundary hpack_boundary_type(grpc_chttp2_transport* t,
   }
 }
 
+static HPackParser::LogInfo hpack_parser_log_info(
+    grpc_chttp2_transport* t, HPackParser::LogInfo::Type type) {
+  return HPackParser::LogInfo{
+      t->incoming_stream_id,
+      type,
+      t->is_client,
+  };
+}
+
 static grpc_error_handle init_header_skip_frame_parser(
     grpc_chttp2_transport* t, HPackParser::Priority priority_type) {
   bool is_eoh = t->expect_continuation_stream_id != 0;
@@ -333,7 +342,8 @@ static grpc_error_handle init_header_skip_frame_parser(
       nullptr,
       t->settings[GRPC_ACKED_SETTINGS]
                  [GRPC_CHTTP2_SETTINGS_MAX_HEADER_LIST_SIZE],
-      hpack_boundary_type(t, is_eoh), priority_type);
+      hpack_boundary_type(t, is_eoh), priority_type,
+      hpack_parser_log_info(t, HPackParser::LogInfo::kDontKnow));
   return GRPC_ERROR_NONE;
 }
 
@@ -504,6 +514,7 @@ static grpc_error_handle init_header_frame_parser(grpc_chttp2_transport* t,
     s->eos_received = true;
   }
   grpc_metadata_batch* incoming_metadata_buffer = nullptr;
+  HPackParser::LogInfo::Type frame_type = HPackParser::LogInfo::kDontKnow;
   switch (s->header_frames_received) {
     case 0:
       if (t->is_client && t->header_eof) {
@@ -512,14 +523,17 @@ static grpc_error_handle init_header_frame_parser(grpc_chttp2_transport* t,
           *s->trailing_metadata_available = true;
         }
         incoming_metadata_buffer = &s->trailing_metadata_buffer;
+        frame_type = HPackParser::LogInfo::kTrailers;
       } else {
         GRPC_CHTTP2_IF_TRACING(gpr_log(GPR_INFO, "parsing initial_metadata"));
         incoming_metadata_buffer = &s->initial_metadata_buffer;
+        frame_type = HPackParser::LogInfo::kHeaders;
       }
       break;
     case 1:
       GRPC_CHTTP2_IF_TRACING(gpr_log(GPR_INFO, "parsing trailing_metadata"));
       incoming_metadata_buffer = &s->trailing_metadata_buffer;
+      frame_type = HPackParser::LogInfo::kTrailers;
       break;
     case 2:
       gpr_log(GPR_ERROR, "too many header frames received");
@@ -529,7 +543,8 @@ static grpc_error_handle init_header_frame_parser(grpc_chttp2_transport* t,
       incoming_metadata_buffer,
       t->settings[GRPC_ACKED_SETTINGS]
                  [GRPC_CHTTP2_SETTINGS_MAX_HEADER_LIST_SIZE],
-      hpack_boundary_type(t, is_eoh), priority_type);
+      hpack_boundary_type(t, is_eoh), priority_type,
+      hpack_parser_log_info(t, frame_type));
   return GRPC_ERROR_NONE;
 }
 

test/core/transport/chttp2/hpack_parser_fuzzer_test.cc

@@ -64,7 +64,10 @@ DEFINE_PROTO_FUZZER(const hpack_parser_fuzzer::Msg& msg) {
         max_length = frame.max_metadata_length();
       }
 
-      parser->BeginFrame(&b, max_length, boundary, priority);
+      parser->BeginFrame(
+          &b, max_length, boundary, priority,
+          grpc_core::HPackParser::LogInfo{
+              1, grpc_core::HPackParser::LogInfo::kHeaders, false});
       int stop_buffering_ctr =
           std::max(-1, frame.stop_buffering_after_segments());
       for (const auto& parse : frame.parse()) {

test/core/transport/chttp2/hpack_parser_test.cc

@@ -75,8 +75,11 @@ class ParseTest : public ::testing::TestWithParam<Test> {
 
     grpc_metadata_batch b(arena.get());
 
-    parser_->BeginFrame(&b, 4096, grpc_core::HPackParser::Boundary::None,
+    parser_->BeginFrame(
-                        grpc_core::HPackParser::Priority::None);
+        &b, 4096, grpc_core::HPackParser::Boundary::None,
+        grpc_core::HPackParser::Priority::None,
+        grpc_core::HPackParser::LogInfo{
+            1, grpc_core::HPackParser::LogInfo::kHeaders, false});
 
     grpc_split_slices(mode, &input, 1, &slices, &nslices);
     grpc_slice_unref(input);

test/cpp/microbenchmarks/bm_chttp2_hpack.cc

@@ -449,7 +449,9 @@ static void BM_HpackParserParseHeader(benchmark::State& state) {
   b.Init(arena);
   p.BeginFrame(&*b, std::numeric_limits<uint32_t>::max(),
                grpc_core::HPackParser::Boundary::None,
-               grpc_core::HPackParser::Priority::None);
+               grpc_core::HPackParser::Priority::None,
+               grpc_core::HPackParser::LogInfo{
+                   1, grpc_core::HPackParser::LogInfo::kHeaders, false});
   for (auto slice : init_slices) {
     GPR_ASSERT(GRPC_ERROR_NONE == p.Parse(slice, false));
   }
@@ -467,7 +469,9 @@ static void BM_HpackParserParseHeader(benchmark::State& state) {
       b.Init(arena);
       p.BeginFrame(&*b, std::numeric_limits<uint32_t>::max(),
                    grpc_core::HPackParser::Boundary::None,
-                   grpc_core::HPackParser::Priority::None);
+                   grpc_core::HPackParser::Priority::None,
+                   grpc_core::HPackParser::LogInfo{
+                       1, grpc_core::HPackParser::LogInfo::kHeaders, false});
     }
   }
   // Clean up