HTTP1: Add DumpState support for HTTP1. by KBaichoo · Pull Request #14812 · envoyproxy/envoy

KBaichoo · 2021-01-25T13:53:14Z

Signed-off-by: Kevin Baichoo [email protected]

For an explanation of how to fill out the fields, please see the relevant section
in PULL_REQUESTS.md

Commit Message: HTTP1: Add DumpState support for HTTP1.
Additional Description: While dispatching, the HTTP1 Connection object registers itself as a scopetrackedobject. If we crash during parsing pipeline, we'll dump information such as the partial headers parsed, current buffer, headermap, etc.
Risk Level: medium
Testing: unit tests
Docs Changes: N/A
Release Notes: Included
Platform Specific Features: N/A
Related Issue #14249

/assign @antoniovicente

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo · 2021-01-25T18:44:41Z

/retest

repokitteh-read-only · 2021-01-25T18:44:45Z

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #14812 (comment) was created by @KBaichoo.

see: more, trace.

antoniovicente

Thanks for further improving debug dumps when crashing in H1 parsing.

antoniovicente · 2021-01-25T20:19:42Z

source/common/http/http1/codec_impl.cc

+  };
+
+  os << DUMP_NULLABLE_MEMBER(current_dispatching_buffer_, dumpBuffer(current_dispatching_buffer_));
+  os << DUMP_MEMBER(buffered_body_, dumpBuffer(&buffered_body_));


I think we shoud consider dumping just buffered_body_.length() or omit this field, the body contents is not that relevant. The current_dispatching_buffer_ seems more relevant.

Will dump the length.

source/common/http/http1/codec_impl.cc

antoniovicente · 2021-01-25T20:21:10Z

source/common/http/http1/codec_impl.cc

+  // Dump the first slice of the dispatching buffer and buffered_body if
+  // applicable.
+  auto dumpBuffer = [](auto* instance) {
+    auto slice = instance->frontSlice();


Should you quote and escape the buffer contents? Should you explicitly dump the size of the slice?

I explicitly dump the size of the slice now.

The buffer contents are escaped in \t, \r, \n, ', " and \

antoniovicente · 2021-01-25T20:24:57Z

source/common/http/http1/codec_impl.cc

+    return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);
+  };
+
+  os << DUMP_NULLABLE_MEMBER(current_dispatching_buffer_, dumpBuffer(current_dispatching_buffer_));


Parsing is a destructive operation on current_dispatching_buffer_ in some cases involving processing bodies. I guess this may dump the wrong slice in those cases. That said, crashing while processing body is unlikely; crashes during header parse should produce the right output.

Will not dump the first slice then if the dispatching buffer is already drained.

source/common/http/http1/codec_impl.cc

antoniovicente · 2021-01-25T20:43:27Z

source/common/http/http1/codec_impl.cc

+  // applicable.
+  auto dumpBuffer = [](auto* instance) {
+    auto slice = instance->frontSlice();
+    return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);


Excellent, I see tests that cover dumping of current_dispatching_buffer_ in
Http1ClientConnectionImplTest.ShouldDumpBuffersWithoutAllocatingMemory.

antoniovicente · 2021-01-25T20:49:15Z

source/common/http/http1/codec_impl.cc

+    os << DUMP_MEMBER(current_header_value_, current_header_value_.getStringView());
+  }
+
+  // Dump Child


I think that the dump for current_dispatching_buffer_ should be done via DUMP_DETAILS. Consider putting it after the dump of header maps in subclasses. Reasoning: buffer contents can be long and may contain newlines

Makes sense; It's now after the dump of header maps. By "via DUMP_DETAILS" I'm interpreting that as dumping the buffer in a similar style as the macro would do.

We could explicitly add a dumpState method to the buffer if that's what you meant, but given we're just dumping the first slice.

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo

Thanks for the review Antonio.

source/common/http/http1/codec_impl.cc

KBaichoo · 2021-01-26T01:42:17Z

source/common/http/http1/codec_impl.cc

+  };
+
+  os << DUMP_NULLABLE_MEMBER(current_dispatching_buffer_, dumpBuffer(current_dispatching_buffer_));
+  os << DUMP_MEMBER(buffered_body_, dumpBuffer(&buffered_body_));


Will dump the length.

KBaichoo · 2021-01-26T01:46:43Z

source/common/http/http1/codec_impl.cc

+    os << DUMP_MEMBER(current_header_value_, current_header_value_.getStringView());
+  }
+
+  // Dump Child


Makes sense; It's now after the dump of header maps. By "via DUMP_DETAILS" I'm interpreting that as dumping the buffer in a similar style as the macro would do.

We could explicitly add a dumpState method to the buffer if that's what you meant, but given we're just dumping the first slice.

KBaichoo · 2021-01-26T18:28:50Z

source/common/http/http1/codec_impl.cc

+  // Dump the first slice of the dispatching buffer and buffered_body if
+  // applicable.
+  auto dumpBuffer = [](auto* instance) {
+    auto slice = instance->frontSlice();


I explicitly dump the size of the slice now.

KBaichoo · 2021-01-26T20:09:54Z

source/common/http/http1/codec_impl.cc

+    return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);
+  };
+
+  os << DUMP_NULLABLE_MEMBER(current_dispatching_buffer_, dumpBuffer(current_dispatching_buffer_));


Will not dump the first slice then if the dispatching buffer is already drained.

Signed-off-by: Kevin Baichoo <[email protected]>

antoniovicente

Just a few nits, thanks again for improving crash dump coverage.

source/common/http/http1/codec_impl.cc

antoniovicente · 2021-01-27T07:06:27Z

source/common/http/http1/codec_impl.cc

+      return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);
+    }(current_dispatching_buffer_);
+
+    os << spaces << DUMP_MEMBER(front_slice.length(), front_slice.length()) << ", front_slice: \n";


I would consider doing the following here:

os << spaces << "current_dispatching_buffer_ front_slice length: " << front_slice.length() << " contents: \"" << StringUtil::escapeToOstream(os, front_slice) << "\"\n";

antoniovicente · 2021-01-27T07:14:35Z

test/common/http/http1/codec_impl_test.cc

+  Buffer::OwnedImpl request("POST / HTTP/1.1\r\n"
+                            "Content-Length: 11\r\n"
+                            "\r\n"
+                            "Hello Envoy");


Would it be possible to split the request over 2 slices and verify that only the first slice is logged?

Something like:

Buffer::OwnedImpl request; request.appendSliceForTest("POST / HTTP/1.1\r\n" "Content-Length: 11\r\n" "\r\n" "Hello"); request.appendSliceForTest(" Envoy"); EXPECT_THAT(ostream.contents(), HasSubstr("front_slice.length(): 44 ...

Did something similar to this; We were using onMessageCompleteBase's callback from the parser to dump the data of the buffer.

I added extraneous bytes in the other slice to check that only the front slice is dumped. The content length is used to tell the parser the message should only have the front slice.

source/common/http/http1/codec_impl.cc

…dumped. Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo

Thanks for the review Antonio.

KBaichoo · 2021-01-27T13:50:23Z

source/common/http/http1/codec_impl.cc

+      return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);
+    }(current_dispatching_buffer_);
+
+    os << spaces << DUMP_MEMBER(front_slice.length(), front_slice.length()) << ", front_slice: \n";


KBaichoo · 2021-01-27T14:55:32Z

test/common/http/http1/codec_impl_test.cc

+  Buffer::OwnedImpl request("POST / HTTP/1.1\r\n"
+                            "Content-Length: 11\r\n"
+                            "\r\n"
+                            "Hello Envoy");


Did something similar to this; We were using onMessageCompleteBase's callback from the parser to dump the data of the buffer.

I added extraneous bytes in the other slice to check that only the front slice is dumped. The content length is used to tell the parser the message should only have the front slice.

antoniovicente · 2021-01-27T17:35:13Z

grpc errors during build?

/retest

repokitteh-read-only · 2021-01-27T17:35:17Z

Retrying Azure Pipelines:
Check envoy-presubmit isn't fully completed, but will still attempt retrying.
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #14812 (comment) was created by @antoniovicente.

see: more, trace.

KBaichoo · 2021-01-27T18:51:06Z

Not sure if that restarted it; did run clang-tidy in docker locally no issue...

/retest

repokitteh-read-only · 2021-01-27T18:51:11Z

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #14812 (comment) was created by @KBaichoo.

see: more, trace.

KBaichoo · 2021-01-27T20:04:43Z

grpc issue seems to be due to some loadshedding that some service is performing -- maybe too much going on for CI.

Will re-kick this in a bit, perhaps we should get some other reviewing eyes on it in the mean time?

KBaichoo · 2021-01-27T20:29:07Z

/retest

repokitteh-read-only · 2021-01-27T20:29:12Z

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #14812 (comment) was created by @KBaichoo.

see: more, trace.

KBaichoo · 2021-01-28T14:36:26Z

PTAL @envoyproxy/senior-maintainers; seems like it was LGTM from @antoniovicente, but he's OOO.

jmarantz · 2021-02-01T14:39:41Z

needs main merge.

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo · 2021-02-01T17:15:14Z

/retest

repokitteh-read-only · 2021-02-01T17:15:19Z

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #14812 (comment) was created by @KBaichoo.

see: more, trace.

Signed-off-by: Kevin Baichoo <[email protected]>

antoniovicente

Some style nits, looks good otherwise.

docs/root/version_history/current.rst

antoniovicente · 2021-02-01T18:55:28Z

source/common/common/utility.cc

  return ret;
 }

+void StringUtil::escapeToOstream(std::ostream& os, absl::string_view view) {


I think these are the most important to escape, but I can see us also escaping c < ' ' and c >= 127. We can take that on in a followup if we decide it is useful.

Will do in a followup if needed. Added a todo here.

There's also escaping code in source/common/common/logger.cc in DelegatingLogSink::escapeLogLine() which calls absl::CEscape. Can you use that instead?

Nope, absl::CEscape allocs memory via the string it'll create and return. This avoids memory allocs.

antoniovicente · 2021-02-01T18:58:36Z

source/common/http/http1/codec_impl.cc


+void ConnectionImpl::dumpState(std::ostream& os, int indent_level) const {
+  const char* spaces = spacesForLevel(indent_level);
+  // Dump all bool to provide context


This comment is not 100% accurate; not all the dumped members are of bool type.

Removed it.

antoniovicente · 2021-02-01T18:59:02Z

source/common/http/http1/codec_impl.cc

+  os << '\n';
+  dumpAdditionalState(os, indent_level);
+
+  // Dump the first slice of the dispatching buffer if not drained.


Explain why we are doing this last.

antoniovicente · 2021-02-01T18:59:56Z

source/common/http/http1/codec_impl.cc

+  } else if (header_parsing_state_ == HeaderParsingState::Value) {
+    os << DUMP_MEMBER(current_header_field_, current_header_field_.getStringView());
+    os << DUMP_MEMBER(current_header_value_, current_header_value_.getStringView());
+  }


We could unconditionally dump both current_header_field_ and current_header_value_

antoniovicente · 2021-02-01T19:10:06Z

source/common/http/http1/codec_impl.cc

+    auto front_slice = [](Buffer::Instance* instance) {
+      auto slice = instance->frontSlice();
+      return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);
+    }(current_dispatching_buffer_);


The previous 4 lines are hard to follow due to the inline lambda use and excessive use of 'auto'.

Consider instead:

absl::string_view front_slice = [](RawSlice slice) { return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_); }(current_dispatching_buffer_->frontSlice());

or

auto to_str_view = [](RawSlice slice) { return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_); }; absl::string_view front_slice = to_str_view(current_dispatching_buffer_->frontSlice());

went with the former.

antoniovicente · 2021-02-01T19:15:38Z

source/common/common/dump_state_utils.h

+
+// If DUMP_MEMBER is called with one argument, then _DUMP_MEMBER is called.
+// If DUMP_MEMBER is called with two arguments, then _DUMP_MEMBER_VIA_VALUE is called.
+#define DUMP_MEMBER(...)                                                                           \


Code would be easier to follow if you use a different macro name in cases we want to override how the member is printed. Something like:

#define DUMP_MEMBER_VIA_VALUE(member, value) ", " #member ": " << (value)

Other possible macro names include DUMP_MEMBER_VIA and DUMP_MEMBER_AS

sg. will go with DUMP_MEMBER_AS.

antoniovicente · 2021-02-01T19:21:55Z

test/common/http/http1/codec_impl_test.cc

      .WillOnce(Invoke([&](ResponseHeaderMapPtr&, bool) {
-        // Fake a call for going below the low watermark. Make sure no stream callbacks get called.
+        // Fake a call for going below the low watermark. Make sure no stream callbacks get
+        // called.


Unclear why the previous 3 whitespace changes were done. Was it the fix format script or a consequence of some indent change that was later backed out?

The latter, I've reverted it.

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo

Thanks for the review @antoniovicente

KBaichoo · 2021-02-01T20:59:59Z

source/common/http/http1/codec_impl.cc


+void ConnectionImpl::dumpState(std::ostream& os, int indent_level) const {
+  const char* spaces = spacesForLevel(indent_level);
+  // Dump all bool to provide context


Removed it.

KBaichoo · 2021-02-01T21:00:43Z

source/common/http/http1/codec_impl.cc

+  os << '\n';
+  dumpAdditionalState(os, indent_level);
+
+  // Dump the first slice of the dispatching buffer if not drained.


KBaichoo · 2021-02-01T21:03:44Z

source/common/http/http1/codec_impl.cc

+    auto front_slice = [](Buffer::Instance* instance) {
+      auto slice = instance->frontSlice();
+      return absl::string_view(static_cast<const char*>(slice.mem_), slice.len_);
+    }(current_dispatching_buffer_);


went with the former.

KBaichoo · 2021-02-01T21:13:34Z

source/common/common/dump_state_utils.h

+
+// If DUMP_MEMBER is called with one argument, then _DUMP_MEMBER is called.
+// If DUMP_MEMBER is called with two arguments, then _DUMP_MEMBER_VIA_VALUE is called.
+#define DUMP_MEMBER(...)                                                                           \


sg. will go with DUMP_MEMBER_AS.

KBaichoo · 2021-02-01T21:14:24Z

source/common/common/utility.cc

  return ret;
 }

+void StringUtil::escapeToOstream(std::ostream& os, absl::string_view view) {


Will do in a followup if needed. Added a todo here.

KBaichoo · 2021-02-01T21:22:53Z

source/common/http/http1/codec_impl.cc

+  } else if (header_parsing_state_ == HeaderParsingState::Value) {
+    os << DUMP_MEMBER(current_header_field_, current_header_field_.getStringView());
+    os << DUMP_MEMBER(current_header_value_, current_header_value_.getStringView());
+  }


KBaichoo · 2021-02-01T21:34:08Z

test/common/http/http1/codec_impl_test.cc

      .WillOnce(Invoke([&](ResponseHeaderMapPtr&, bool) {
-        // Fake a call for going below the low watermark. Make sure no stream callbacks get called.
+        // Fake a call for going below the low watermark. Make sure no stream callbacks get
+        // called.


The latter, I've reverted it.

Signed-off-by: Kevin Baichoo <[email protected]>

source/common/common/utility.cc

antoniovicente · 2021-02-01T23:03:44Z

source/common/http/http1/codec_impl.cc

+                       active_request_.has_value() &&
+                               !active_request_.value().request_url_.getStringView().empty()
+                           ? active_request_.value().request_url_.getStringView()
+                           : "null\n");


there's a trailing newline after "null", but no similar newline is added when the URL is not empty.

Done, they both have the newline now.

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo · 2021-02-02T02:41:14Z

PTAL @ggreenway since you're the maintainer on-call this week. Thanks!

KBaichoo · 2021-02-02T15:04:30Z

/retest

Flaky integration test.

repokitteh-read-only · 2021-02-02T15:04:35Z

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #14812 (comment) was created by @KBaichoo.

see: more, trace.

snowp

Awesome, this looks super useful!

Dump H1 debug information if crashing during parsing.

125129d

Signed-off-by: Kevin Baichoo <[email protected]>

repokitteh-read-only bot assigned antoniovicente Jan 25, 2021

antoniovicente reviewed Jan 25, 2021

View reviewed changes

Minor changes.

5bbe8ed

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo commented Jan 26, 2021

View reviewed changes

Added escaping support for dumping the buffer.

090ce6c

Signed-off-by: Kevin Baichoo <[email protected]>

antoniovicente reviewed Jan 27, 2021

View reviewed changes

antoniovicente added the waiting label Jan 27, 2021

Minor fixes in formatting, improve test to check only front slice is …

0df63f0

…dumped. Signed-off-by: Kevin Baichoo <[email protected]>

repokitteh-read-only bot removed the waiting label Jan 27, 2021

KBaichoo commented Jan 27, 2021

View reviewed changes

KBaichoo added 2 commits February 1, 2021 14:49

Merge remote-tracking branch 'upstream/main' into bufferDump

97af1ce

Signed-off-by: Kevin Baichoo <[email protected]>

Version history.

813be1b

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo added 2 commits February 1, 2021 18:39

Merge remote-tracking branch 'upstream/main' into bufferDump

ca7d535

Signed-off-by: Kevin Baichoo <[email protected]>

Version history merge.

81c9ee9

Signed-off-by: Kevin Baichoo <[email protected]>

antoniovicente reviewed Feb 1, 2021

View reviewed changes

Minor cleanup: naming, comments, etc.

020ed25

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo commented Feb 1, 2021

View reviewed changes

Merge remote-tracking branch 'upstream/main' into bufferDump

d3a50a5

Signed-off-by: Kevin Baichoo <[email protected]>

antoniovicente previously approved these changes Feb 1, 2021

View reviewed changes

Minor nits.

5d3838b

Signed-off-by: Kevin Baichoo <[email protected]>

KBaichoo dismissed antoniovicente’s stale review via 5d3838b February 2, 2021 02:32

antoniovicente approved these changes Feb 2, 2021

View reviewed changes

ggreenway assigned alyssawilk and snowp and unassigned alyssawilk Feb 2, 2021

snowp approved these changes Feb 2, 2021

View reviewed changes

snowp merged commit 1ce7fab into envoyproxy:main Feb 2, 2021

KBaichoo mentioned this pull request Feb 3, 2021

HTTP2: Add DumpState support for HTTP2 #14923

Merged

Conversation

KBaichoo commented Jan 25, 2021

Uh oh!

KBaichoo commented Jan 25, 2021

Uh oh!

repokitteh-read-only bot commented Jan 25, 2021

Uh oh!

antoniovicente left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

KBaichoo left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

antoniovicente left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

KBaichoo left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

antoniovicente commented Jan 27, 2021

Uh oh!

repokitteh-read-only bot commented Jan 27, 2021

Uh oh!

KBaichoo commented Jan 27, 2021

Uh oh!

repokitteh-read-only bot commented Jan 27, 2021

Uh oh!

KBaichoo commented Jan 27, 2021

Uh oh!

KBaichoo commented Jan 27, 2021

Uh oh!

repokitteh-read-only bot commented Jan 27, 2021

Uh oh!