access_log: log requested_server_name in tcp proxy (#4144)

cmluciano · ggreenway · commit 5fa8192a3304 · 2018-08-28T13:16:41.000-07:00
* access_log: log requested_server_name

Signed-off-by: Christopher M. Luciano &lt;cmluciano@us.ibm.com&gt;
diff --git a/docs/root/configuration/access_log.rst b/docs/root/configuration/access_log.rst
@@ -227,6 +227,12 @@ The following command operators are supported:
   TCP
     Not implemented ("-").
 
+%REQUESTED_SERVER_NAME%
+  HTTP
+    String value set on ssl connection socket for Server Name Indication (SNI)
+  TCP
+    String value set on ssl connection socket for Server Name Indication (SNI)
+
 .. _config_access_log_default_format:
 
 Default format
diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst
@@ -6,6 +6,7 @@ Version history
 * access log: added :ref:`response flag filter <envoy_api_msg_config.filter.accesslog.v2.ResponseFlagFilter>`
   to filter based on the presence of Envoy response flags.
 * access log: added RESPONSE_DURATION and RESPONSE_TX_DURATION.
+* access log: added REQUESTED_SERVER_NAME for SNI to tcp_proxy and http
 * admin: added :http:get:`/hystrix_event_stream` as an endpoint for monitoring envoy's statistics
   through `Hystrix dashboard <https://github.com/Netflix-Skunkworks/hystrix-dashboard/wiki>`_.
 * grpc-json: added support for building HTTP response from
diff --git a/include/envoy/request_info/request_info.h b/include/envoy/request_info/request_info.h
@@ -303,6 +303,16 @@ class RequestInfo {
    * the same key overriding existing.
    */
   virtual void setDynamicMetadata(const std::string& name, const ProtobufWkt::Struct& value) PURE;
+
+  /**
+   * @param SNI value requested
+   */
+  virtual void setRequestedServerName(const absl::string_view requested_server_name) PURE;
+
+  /**
+   * @return SNI value for downstream host
+   */
+  virtual const std::string& requestedServerName() const PURE;
 };
 
 } // namespace RequestInfo
diff --git a/source/common/access_log/access_log_formatter.cc b/source/common/access_log/access_log_formatter.cc
@@ -301,6 +301,14 @@ RequestInfoFormatter::RequestInfoFormatter(const std::string& field_name) {
       return RequestInfo::Utility::formatDownstreamAddressNoPort(
           *request_info.downstreamRemoteAddress());
     };
+  } else if (field_name == "REQUESTED_SERVER_NAME") {
+    field_extractor_ = [](const RequestInfo::RequestInfo& request_info) {
+      if (!request_info.requestedServerName().empty()) {
+        return request_info.requestedServerName();
+      } else {
+        return UnspecifiedValueString;
+      }
+    };
   } else {
     throw EnvoyException(fmt::format("Not supported field in RequestInfo: {}", field_name));
   }
diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc
@@ -379,6 +379,8 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect
         [this]() -> void { onIdleTimeout(); });
     resetIdleTimer();
   }
+  request_info_.setRequestedServerName(
+      connection_manager_.read_callbacks_->connection().requestedServerName());
 }
 
 ConnectionManagerImpl::ActiveStream::~ActiveStream() {
diff --git a/source/common/request_info/request_info_impl.h b/source/common/request_info/request_info_impl.h
@@ -178,6 +178,12 @@ struct RequestInfoImpl : public RequestInfo {
     (*metadata_.mutable_filter_metadata())[name].MergeFrom(value);
   };
 
+  void setRequestedServerName(absl::string_view requested_server_name) override {
+    requested_server_name_ = std::string(requested_server_name);
+  }
+
+  const std::string& requestedServerName() const override { return requested_server_name_; }
+
   const SystemTime start_time_;
   const MonotonicTime start_time_monotonic_;
 
@@ -204,6 +210,7 @@ struct RequestInfoImpl : public RequestInfo {
   Network::Address::InstanceConstSharedPtr upstream_local_address_;
   Network::Address::InstanceConstSharedPtr downstream_local_address_;
   Network::Address::InstanceConstSharedPtr downstream_remote_address_;
+  std::string requested_server_name_;
 };
 
 } // namespace RequestInfo
diff --git a/source/common/tcp_proxy/tcp_proxy.cc b/source/common/tcp_proxy/tcp_proxy.cc
@@ -462,6 +462,10 @@ void Filter::onUpstreamEvent(Network::ConnectionEvent event) {
         Upstream::Outlier::Result::SUCCESS);
     onConnectionSuccess();
 
+    getRequestInfo().setRequestedServerName(read_callbacks_->connection().requestedServerName());
+    ENVOY_LOG(debug, "TCP:onUpstreamEvent(), requestedServerName: {}",
+              getRequestInfo().requestedServerName());
+
     if (config_->idleTimeout()) {
       // The idle_timer_ can be moved to a Drainer, so related callbacks call into
       // the UpstreamCallbacks, which has the same lifetime as the timer, and can dispatch
diff --git a/source/extensions/filters/listener/tls_inspector/tls_inspector.cc b/source/extensions/filters/listener/tls_inspector/tls_inspector.cc
@@ -123,6 +123,7 @@ void Filter::onServername(absl::string_view name) {
   if (!name.empty()) {
     config_->stats().sni_found_.inc();
     cb_->socket().setRequestedServerName(name);
+    ENVOY_LOG(debug, "tls:onServerName(), requestedServerName: {}", name);
   } else {
     config_->stats().sni_not_found_.inc();
   }
diff --git a/test/common/access_log/access_log_formatter_test.cc b/test/common/access_log/access_log_formatter_test.cc
@@ -185,6 +185,22 @@ TEST(AccessLogFormatterTest, requestInfoFormatter) {
     RequestInfoFormatter upstream_format("DOWNSTREAM_REMOTE_ADDRESS");
     EXPECT_EQ("127.0.0.1:0", upstream_format.format(header, header, header, request_info));
   }
+
+  {
+    RequestInfoFormatter upstream_format("REQUESTED_SERVER_NAME");
+    std::string requested_server_name = "stub_server";
+    EXPECT_CALL(request_info, requestedServerName())
+        .WillRepeatedly(ReturnRef(requested_server_name));
+    EXPECT_EQ("stub_server", upstream_format.format(header, header, header, request_info));
+  }
+
+  {
+    RequestInfoFormatter upstream_format("REQUESTED_SERVER_NAME");
+    std::string requested_server_name;
+    EXPECT_CALL(request_info, requestedServerName())
+        .WillRepeatedly(ReturnRef(requested_server_name));
+    EXPECT_EQ("-", upstream_format.format(header, header, header, request_info));
+  }
 }
 
 TEST(AccessLogFormatterTest, requestHeaderFormatter) {
diff --git a/test/common/access_log/test_util.h b/test/common/access_log/test_util.h
@@ -156,6 +156,12 @@ class TestRequestInfo : public RequestInfo::RequestInfo {
     (*metadata_.mutable_filter_metadata())[name].MergeFrom(value);
   };
 
+  void setRequestedServerName(const absl::string_view requested_server_name) override {
+    requested_server_name_ = std::string(requested_server_name);
+  }
+
+  const std::string& requestedServerName() const override { return requested_server_name_; }
+
   SystemTime start_time_;
   MonotonicTime start_time_monotonic_;
 
@@ -178,6 +184,7 @@ class TestRequestInfo : public RequestInfo::RequestInfo {
   Network::Address::InstanceConstSharedPtr downstream_remote_address_;
   const Router::RouteEntry* route_entry_{};
   envoy::api::v2::core::Metadata metadata_{};
+  std::string requested_server_name_;
 };
 
 } // namespace Envoy
diff --git a/test/common/request_info/request_info_impl_test.cc b/test/common/request_info/request_info_impl_test.cc
@@ -140,6 +140,11 @@ TEST(RequestInfoImplTest, MiscSettersAndGetters) {
     NiceMock<Router::MockRouteEntry> route_entry;
     request_info.route_entry_ = &route_entry;
     EXPECT_EQ(&route_entry, request_info.routeEntry());
+
+    EXPECT_EQ("", request_info.requestedServerName());
+    absl::string_view sni_name = "stubserver.org";
+    request_info.setRequestedServerName(sni_name);
+    EXPECT_EQ(std::string(sni_name), request_info.requestedServerName());
   }
 }
 
diff --git a/test/mocks/request_info/mocks.cc b/test/mocks/request_info/mocks.cc
@@ -64,6 +64,11 @@ MockRequestInfo::MockRequestInfo()
   }));
   ON_CALL(*this, bytesSent()).WillByDefault(ReturnPointee(&bytes_sent_));
   ON_CALL(*this, dynamicMetadata()).WillByDefault(ReturnRef(metadata_));
+  ON_CALL(*this, setRequestedServerName(_))
+      .WillByDefault(Invoke([this](const absl::string_view requested_server_name) {
+        requested_server_name_ = std::string(requested_server_name);
+      }));
+  ON_CALL(*this, requestedServerName()).WillByDefault(ReturnRef(requested_server_name_));
 }
 
 MockRequestInfo::~MockRequestInfo() {}
diff --git a/test/mocks/request_info/mocks.h b/test/mocks/request_info/mocks.h
@@ -60,6 +60,8 @@ class MockRequestInfo : public RequestInfo {
   MOCK_METHOD2(setDynamicMetadata, void(const std::string&, const ProtobufWkt::Struct&));
   MOCK_METHOD3(setDynamicMetadata,
                void(const std::string&, const std::string&, const std::string&));
+  MOCK_METHOD1(setRequestedServerName, void(const absl::string_view));
+  MOCK_CONST_METHOD0(requestedServerName, const std::string&());
 
   std::shared_ptr<testing::NiceMock<Upstream::MockHostDescription>> host_{
       new testing::NiceMock<Upstream::MockHostDescription>()};
@@ -81,6 +83,7 @@ class MockRequestInfo : public RequestInfo {
   Network::Address::InstanceConstSharedPtr upstream_local_address_;
   Network::Address::InstanceConstSharedPtr downstream_local_address_;
   Network::Address::InstanceConstSharedPtr downstream_remote_address_;
+  std::string requested_server_name_;
 };
 
 } // namespace RequestInfo

Original file line number	Diff line number	Diff line change
`@@ -379,6 +379,8 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect`
`379`	`379`	`[this]() -> void { onIdleTimeout(); });`
`380`	`380`	`resetIdleTimer();`
`381`	`381`	`}`
	`382`	`+ request_info_.setRequestedServerName(`
	`383`	`+ connection_manager_.read_callbacks_->connection().requestedServerName());`
`382`	`384`	`}`
`383`	`385`
`384`	`386`	`ConnectionManagerImpl::ActiveStream::~ActiveStream() {`
Original file line number	Diff line number	Diff line change
`@@ -123,6 +123,7 @@ void Filter::onServername(absl::string_view name) {`
`123`	`123`	`if (!name.empty()) {`
`124`	`124`	`config_->stats().sni_found_.inc();`
`125`	`125`	`cb_->socket().setRequestedServerName(name);`
	`126`	`+ ENVOY_LOG(debug, "tls:onServerName(), requestedServerName: {}", name);`
`126`	`127`	`} else {`
`127`	`128`	`config_->stats().sni_not_found_.inc();`
`128`	`129`	`}`