access_log: log requested_server_name in tcp proxy #4144

cmluciano · 2018-08-14T17:10:03Z

Signed-off-by: Christopher M. Luciano [email protected]

Description: log SNI value when configured in TCP access log
Risk Level: low
Testing: current and new tests pass & manual testing with 2 envoys & tcp emitted the correct log entry
Docs Changes: WIP
Release Notes: WIP
Fixes: #3874

Signed-off-by: Christopher M. Luciano <[email protected]>

mattklein123 · 2018-08-14T17:59:29Z

Assigning over to @zuercher. @cmluciano note this change needs docs/release notes. Thank you!

zuercher

I think the general shape of this is correct, but I have some concerns about the use absl::string_view for storing the server name.

zuercher · 2018-08-14T19:43:43Z

include/envoy/request_info/request_info.h

+  /**
+   * @param SNI value requested
+   */
+  virtual void setRequestedServerName(const absl::string_view& requested_server_name) PURE;


I believe we normally pass absl::string_view around by value unless we're modifying it in the call.

zuercher · 2018-08-14T19:58:47Z

source/common/request_info/request_info_impl.h

@@ -197,13 +203,15 @@ struct RequestInfoImpl : public RequestInfo {
  bool hc_request_{};
  const Router::RouteEntry* route_entry_{};
  envoy::api::v2::core::Metadata metadata_{};
+  absl::string_view requestedServerName_;


I think this one's unused.

zuercher · 2018-08-14T19:59:40Z

source/common/request_info/request_info_impl.h


 private:
  uint64_t bytes_received_{};
  uint64_t bytes_sent_{};
  Network::Address::InstanceConstSharedPtr upstream_local_address_;
  Network::Address::InstanceConstSharedPtr downstream_local_address_;
  Network::Address::InstanceConstSharedPtr downstream_remote_address_;
+  absl::string_view requested_server_name_;


Is it always safe to store this as a string view? (e.g. can the underlying string get deallocated before the RequestInfo is used). Given that this is going to get converted into a std::string when the extractor lambda runs, maybe we should just store it as a std::string to begin with?

I was wondering this as well. I just noted some of the lifetime best-practices here. In the access log case, maybe it would probably be safest to store as std::string or still accept string_view but immediately convert with string(string_view).

I only used absl::string_view since we pass it in include/envoy/network/listen_socket.h and include/envoy/connection.h.

I think it's safe, provided 2 things:

the name is only set once for a listener socket/connection and never changed. That implies TLS must not be renegotiated mid-connection. I don't know enough about TLS to know if that's true or not.

AccessLog::Instance implementations cannot keep the RequestInfoImpl object beyond the lifetime of the listener, which I think means beyond the call to log -- e.g. if they buffer log data it must have already been converted into a another format. The file and grpc loggers do their conversion in log. The route_entry_ field also requires this behavior, so we're not worse off here.

I think in the end the fact that it's hard to reason about whether that string_view is still valid means we should copy it just to be safe unless there's a known performance implication.

Did you decide there's a performance implication and want to keep the string view?

cc @htuch @PiotrSikora since they may be more familiar with absl::string_view than I and may have more guidelines for it's lifetime quirks

Yeah, should be safe, but given how much other stuff is in RequestInfoImpl, a copy is probably fast enough and safe; e.g. maybe you server name is only 12 bytes on average, that's like 1.5 pointers worth of space/copy overhead.

zuercher · 2018-08-14T20:00:47Z

source/common/tcp_proxy/tcp_proxy.cc

@@ -388,6 +388,9 @@ Network::FilterStatus Filter::onData(Buffer::Instance& data, bool end_stream) {
  upstream_connection_->write(data, end_stream);
  ASSERT(0 == data.length());
  resetIdleTimer(); // TODO(ggreenway) PERF: do we need to reset timer on both send and receive?
+  getRequestInfo().setRequestedServerName(read_callbacks_->connection().requestedServerName());
+  ENVOY_LOG(debug, "TCP:onData(), requestedServerName: {} ",
+            getRequestInfo().requestedServerName());


FYI: I think the coverage tests are failing because they enable trace-level logging and either this (or one of the other log messages) is being invoked in a test that doesn't set up the mock.

Ack, yep that sounds right upon downloading the results

You should be able to reproduce just by running regular tests with --test_arg="-l trace".

zuercher · 2018-08-14T20:01:11Z

test/common/access_log/access_log_formatter_test.cc

+  //   EXPECT_CALL(request_info,
+  //   requestedServerName()).WillRepeatedly(ReturnRef(requested_server_name));
+  //   EXPECT_EQ("stub_server", upstream_format.format(header, header, header, request_info));
+  // }


Should this be enabled?

zuercher · 2018-08-14T20:03:54Z

source/common/access_log/access_log_formatter.cc

+  } else if (field_name == "REQUESTED_SERVER_NAME") {
+    field_extractor_ = [](const RequestInfo::RequestInfo& request_info) {
+      absl::string_view requested_server_name;
+      if (nullptr != request_info.requestedServerName()) {


This seems odd to me. I think !request_info.requestedServerName().empty() will tell you if the requested server name is set.

zuercher · 2018-08-14T20:04:37Z

test/common/access_log/access_log_formatter_test.cc

+
+  {
+    RequestInfoFormatter upstream_format("REQUESTED_SERVER_NAME");
+    // EXPECT_CALL(request_info, requestedServerName()).WillOnce(Return(nullptr));


Should this be enabled?

Signed-off-by: Christopher M. Luciano <[email protected]>

cmluciano · 2018-08-17T20:28:12Z

@zuercher I added a few updates to the docs

zuercher · 2018-08-20T16:30:53Z

source/common/access_log/access_log_formatter.cc

+        return request_info.requestedServerName().data();
+      } else {
+        requested_server_name = UnspecifiedValueString;
+        return requested_server_name.data();


The return type for field_extractor_ is std::string, so it seems to me this converts UnspecifiedValueString into a string_view and then back to std::string. Does return UnspecifiedValueString not work?

If just return UnspecifiedValueString I get a conversion error

source/common/access_log/access_log_formatter.cc: In lambda function: source/common/access_log/access_log_formatter.cc:310:16: error: inconsistent types 'const char*' and 'std::__cxx11::basic_string<char>' deduced for lambda return type return UnspecifiedValueString; ^~~~~~~~~~~~~~~~~~~~~~ source/common/access_log/access_log_formatter.cc:310:16: error: cannot convert 'std::__cxx11::basic_string<char>(Envoy::AccessLog::UnspecifiedValueString)' from type 'std::__cxx11::basic_string<char>' to type 'const char*'

maybe further ammo to support the removal of absl::string_view from this part

I think if you make the lambda's return type explicit ([](const RequestInfo::RequestInfo&) -> std::string { ... } ) it'll probably work, but you might have to convert the absl::string_view in the other return explicitly as well.

zuercher · 2018-08-20T16:30:56Z

source/common/request_info/request_info_impl.h

@@ -197,13 +203,15 @@ struct RequestInfoImpl : public RequestInfo {
  bool hc_request_{};
  const Router::RouteEntry* route_entry_{};
  envoy::api::v2::core::Metadata metadata_{};
+  //  absl::string_view requestedServerName_;


Please remove this.

zuercher · 2018-08-20T16:31:28Z

source/common/request_info/request_info_impl.h


 private:
  uint64_t bytes_received_{};
  uint64_t bytes_sent_{};
  Network::Address::InstanceConstSharedPtr upstream_local_address_;
  Network::Address::InstanceConstSharedPtr downstream_local_address_;
  Network::Address::InstanceConstSharedPtr downstream_remote_address_;
+  absl::string_view requested_server_name_;


Did you decide there's a performance implication and want to keep the string view?

Signed-off-by: Christopher M. Luciano <[email protected]>

ggreenway

Optional but desired: Can you set this on the request_info for http requests also, so this works in both modes?

ggreenway · 2018-08-24T20:24:41Z

source/common/tcp_proxy/tcp_proxy.cc

@@ -388,6 +388,9 @@ Network::FilterStatus Filter::onData(Buffer::Instance& data, bool end_stream) {
  upstream_connection_->write(data, end_stream);
  ASSERT(0 == data.length());
  resetIdleTimer(); // TODO(ggreenway) PERF: do we need to reset timer on both send and receive?
+  getRequestInfo().setRequestedServerName(read_callbacks_->connection().requestedServerName());


onData seems like the wrong place for this call; this will be run everytime downstream data arrives. Is the needed data available in onNewConnection()? At a minimum, have a flag for whether this has happened yet and only do it once.

I was thinking the same upon reviewing where I called this today. I ended up hitting problems with null values in cases of TCP HalfOpen and thought it might make more sense to only do this when there is a confirmed ::Connected.

Signed-off-by: Christopher M. Luciano <[email protected]>

rshriram · 2018-08-26T23:38:18Z

docs/root/configuration/access_log.rst

@@ -227,6 +227,10 @@ The following command operators are supported:
  TCP
    Not implemented ("-").

+%REQUESTED_SERVER_NAME%


Better off naming this as SNI instead of requested server name, for clarity.

I disagree. In the future we may support sniffing the host header out of plaintext http, which is why it is named as it is in the listener filter code. Please leave it as REQUESTED_SERVER_NAME.

Signed-off-by: Christopher M. Luciano <[email protected]>

cmluciano · 2018-08-27T20:23:22Z

Mac build is probably blocked on #4267

zuercher

I'll second @ggreenway's request to add this to the http connection manager as well. I think it would go in ConnectionManagerImpl::ActiveStream::ActiveStream.

I restarted your mac build -- the problem looks like it was a transient error downloading bazel 0.15.2.

zuercher · 2018-08-27T22:49:04Z

source/common/tcp_proxy/tcp_proxy.cc

@@ -472,6 +469,10 @@ void Filter::onUpstreamEvent(Network::ConnectionEvent event) {
        Upstream::Outlier::Result::SUCCESS);
    onConnectionSuccess();

+    getRequestInfo().setRequestedServerName(read_callbacks_->connection().requestedServerName());
+    ENVOY_LOG(debug, "TCP:onData(), requestedServerName: {} ",


nit: Probably should log "onUpstreamEvent" not "onData" and delete the trailing space in the string.

Signed-off-by: Christopher M. Luciano <[email protected]>

cmluciano · 2018-08-28T16:23:47Z

I added the http part to my repo:branch

There seems to be a bit of lag from Github displaying the change-set

Signed-off-by: Christopher M. Luciano <[email protected]>

Pulling the following changes from github.com/envoyproxy/envoy: f936fc6 ssl: serialize accesses to SSL socket factory contexts (envoyproxy#4345) e34dcd6 Fix crash in tcp_proxy (envoyproxy#4323) ae6a252 router: fix matching when all domains have wildcards (envoyproxy#4326) aa06142 test: Stop fake_upstream methods from accidentally succeeding (envoyproxy#4232) 5d73187 rbac: update the authenticated.user to a StringMatcher. (envoyproxy#4250) c6bfc7d time: Event::TimeSystem abstraction to make it feasible to inject time with simulated timers (envoyproxy#4257) 752483e Fixing the fix (envoyproxy#4333) 83487f6 tls: update BoringSSL to ab36a84b (3497). (envoyproxy#4338) 7bc210e test: fixing interactions between waitFor and ignore_spurious_events (envoyproxy#4309) 69474b3 admin: order stats in clusters json admin (envoyproxy#4306) 2d155f9 ppc64le build (envoyproxy#4183) 07efc6d fix static initialization fiasco problem (envoyproxy#4314) 0b7e3b5 test: Remove declared but undefined class methods (envoyproxy#4297) 1485a13 lua: make sure resetting dynamic metadata wrapper when request info is marked dead d243cd6 test: set to zero when start_time exceeds limit (envoyproxy#4328) 0a1e92a test: fix heap use-after-free in ~IntegrationTestServer. (envoyproxy#4319) cddc732 CONTRIBUTING: Document 'kick-ci' trick. (envoyproxy#4335) f13ef24 docs: remove reference to deprecated value field (envoyproxy#4322) e947a27 router: minor doc fixes in stream idle timeout (envoyproxy#4329) 0c2e998 tcp-proxy: fixing a TCP proxy bug where we attempted to readDisable a closed connection (envoyproxy#4296) 00ffe44 utility: fix strftime overflow handling. (envoyproxy#4321) af1183c Re-enable TcpProxySslIntegrationTest and make the tests pass again. (envoyproxy#4318) 3553461 fuzz: fix H2 codec fuzzer post envoyproxy#4262. (envoyproxy#4311) 42f6048 Proto string issue fix (envoyproxy#4320) 9c492a0 Support Envoy to fetch secrets using SDS service. (envoyproxy#4256) a857219 ratelimit: revert `revert rate limit failure mode config` and add tests (envoyproxy#4303) 1d34172 dns: fix exception unsafe behavior in c-ares callbacks. (envoyproxy#4307) 1212423 alts: add gRPC TSI socket (envoyproxy#4153) f0363ae fuzz: detect client-side resets in H2 codec fuzzer. (envoyproxy#4300) 01aa3f8 test: hopefully deflaking echo integration test (envoyproxy#4304) 1fc0f4b ratelimit: link legacy proto when message is being used (envoyproxy#4308) aa4481e fix rare List::remove(&target) segfault (envoyproxy#4244) 89e0f23 headers: fixing fast fail of size-validation (envoyproxy#4269) 97eba59 build: bump googletest version. (envoyproxy#4293) 0057e22 fuzz: avoid false positives in HCM fuzzer. (envoyproxy#4262) 9d094e5 Revert ac0bd74 (envoyproxy#4295) ddb28a4 Add validation context provider (envoyproxy#4264) 3b47cba added histogram latency information to Hystrix dashboard stream (envoyproxy#3986) cf87d50 docs: update SNI FAQ. (envoyproxy#4285) f952033 config: fix update empty stat for eds (envoyproxy#4276) 329e591 router: Add ability of custom headers to rely on per-request data (envoyproxy#4219) 68d20b4 thrift: refactor build files and imports (envoyproxy#4271) 5fa8192 access_log: log requested_server_name in tcp proxy (envoyproxy#4144) fa45bb4 fuzz: libc++ clocks don't like nanos. (envoyproxy#4282) 53f8944 stats: add symbol table for future stat name encoding (envoyproxy#3927) c987b42 test infra: Remove timeSource() from the ClusterManager api (envoyproxy#4247) cd171d9 websocket: tunneling websockets (and upgrades in general) over H2 (envoyproxy#4188) b9dc5d9 router: disallow :path/host rewriting in request_headers_to_add. (envoyproxy#4220) 0c91011 network: skip socket options and source address for UDS client connections (envoyproxy#4252) da1857d build: fixing a downstream compile error by noting explicit fallthrough (envoyproxy#4265) 9857cfe fuzz: cleanup per-test environment after each fuzz case. (envoyproxy#4253) 52beb06 test: Wrap proto string in std::string before comparison (envoyproxy#4238) f5e219e extensions/thrift_proxy: Add header matching to thrift router (envoyproxy#4239) c9ce5d2 fuzz: track read_disable_count bidirectionally in codec_impl_fuzz_test. (envoyproxy#4260) 35103b3 fuzz: use nanoseconds for SystemTime in RequestInfo. (envoyproxy#4255) ba6ba98 fuzz: make runtime root hermetic in server_fuzz_test. (envoyproxy#4258) b0a9014 time: Add 'format' test to ensure no one directly instantiates Prod*Time from source. (envoyproxy#4248) 8567460 access_log: support beginning of epoch in START_TIME. (envoyproxy#4254) 28d5f41 proto: unify envoy_proto_library/api_proto_library. (envoyproxy#4233) f7d3cb6 http: fix allocation bug introduced in envoyproxy#4211. (envoyproxy#4245) Fixes istio/istio#8310 (once pulled into istio/istio). Signed-off-by: Piotr Sikora <[email protected]>

access_log: log requested_server_name in tcp proxy

8bbdc82

Signed-off-by: Christopher M. Luciano <[email protected]>

mattklein123 assigned zuercher Aug 14, 2018

zuercher requested changes Aug 14, 2018

View reviewed changes

Christopher M. Luciano added 3 commits August 16, 2018 10:33

Address code comments and uncomment working access_log tests

6b04ff5

Signed-off-by: Christopher M. Luciano <[email protected]>

log string_view data in tcp_proxy

c416a01

Signed-off-by: Christopher M. Luciano <[email protected]>

Add requested_server_name to docs and release notes

17cf320

Signed-off-by: Christopher M. Luciano <[email protected]>

zuercher reviewed Aug 20, 2018

View reviewed changes

cmluciano mentioned this pull request Aug 23, 2018

[WIP] Network-Level SNI reader filter #4236

Closed

Christopher M. Luciano added 2 commits August 23, 2018 14:33

remove unused requestedServerName

d8369ab

Signed-off-by: Christopher M. Luciano <[email protected]>

Store requestedServerName as string

5113cb2

Signed-off-by: Christopher M. Luciano <[email protected]>

ggreenway requested changes Aug 24, 2018

View reviewed changes

missing string conversion in accesslog testutil

a39f84b

Signed-off-by: Christopher M. Luciano <[email protected]>

rshriram reviewed Aug 26, 2018

View reviewed changes

Log requested_server_name at connected in tcp_proxy

b3274e5

Signed-off-by: Christopher M. Luciano <[email protected]>

ggreenway previously approved these changes Aug 27, 2018

View reviewed changes

zuercher reviewed Aug 27, 2018

View reviewed changes

log correct message for requestedServerName

d2c6a34

Signed-off-by: Christopher M. Luciano <[email protected]>

cmluciano dismissed ggreenway’s stale review via d2c6a34 August 28, 2018 14:40

Add SNI access_logging to http

7d02b33

Signed-off-by: Christopher M. Luciano <[email protected]>

Kick CI

49f0ffe

Signed-off-by: Christopher M. Luciano <[email protected]>

ggreenway approved these changes Aug 28, 2018

View reviewed changes

zuercher approved these changes Aug 28, 2018

View reviewed changes

ggreenway merged commit 5fa8192 into envoyproxy:master Aug 28, 2018

cmluciano mentioned this pull request Aug 29, 2018

tlsContext interferes with filterChainMatch and TLS inspector #4076

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

access_log: log requested_server_name in tcp proxy #4144

access_log: log requested_server_name in tcp proxy #4144

cmluciano commented Aug 14, 2018

mattklein123 commented Aug 14, 2018

zuercher left a comment

zuercher Aug 14, 2018

zuercher Aug 14, 2018

zuercher Aug 14, 2018

cmluciano Aug 15, 2018

zuercher Aug 15, 2018

zuercher Aug 20, 2018

cmluciano Aug 23, 2018

htuch Aug 23, 2018

zuercher Aug 14, 2018

cmluciano Aug 15, 2018

zuercher Aug 15, 2018

zuercher Aug 14, 2018

zuercher Aug 14, 2018

zuercher Aug 14, 2018

cmluciano commented Aug 17, 2018

zuercher Aug 20, 2018

cmluciano Aug 23, 2018

zuercher Aug 23, 2018

zuercher Aug 20, 2018

zuercher Aug 20, 2018

ggreenway left a comment

ggreenway Aug 24, 2018

cmluciano Aug 24, 2018

rshriram Aug 26, 2018

ggreenway Aug 27, 2018

cmluciano commented Aug 27, 2018

zuercher left a comment

zuercher Aug 27, 2018

cmluciano commented Aug 28, 2018

access_log: log requested_server_name in tcp proxy #4144

access_log: log requested_server_name in tcp proxy #4144

Conversation

cmluciano commented Aug 14, 2018

mattklein123 commented Aug 14, 2018

zuercher left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cmluciano commented Aug 17, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ggreenway left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cmluciano commented Aug 27, 2018

zuercher left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cmluciano commented Aug 28, 2018