Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

access_log: log requested_server_name in tcp proxy #4144

Merged
merged 11 commits into from
Aug 28, 2018
Merged

access_log: log requested_server_name in tcp proxy #4144

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
8bbdc82
access_log: log requested_server_name in tcp proxy
Aug 6, 2018
6b04ff5
Address code comments and uncomment working access_log tests
Aug 16, 2018
c416a01
log string_view data in tcp_proxy
Aug 16, 2018
17cf320
Add requested_server_name to docs and release notes
Aug 16, 2018
d8369ab
remove unused requestedServerName
Aug 23, 2018
5113cb2
Store requestedServerName as string
Aug 24, 2018
a39f84b
missing string conversion in accesslog testutil
Aug 24, 2018
b3274e5
Log requested_server_name at connected in tcp_proxy
Aug 27, 2018
d2c6a34
log correct message for requestedServerName
Aug 28, 2018
7d02b33
Add SNI access_logging to http
Aug 28, 2018
49f0ffe
Kick CI
Aug 28, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions include/envoy/request_info/request_info.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -301,6 +301,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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


/**
* @return SNI value for downstream host
*/
virtual const absl::string_view& requestedServerName() const PURE;
};

} // namespace RequestInfo
Expand Down
10 changes: 10 additions & 0 deletions source/common/access_log/access_log_formatter.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -301,6 +301,16 @@ 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) {
absl::string_view requested_server_name;
if (nullptr != request_info.requestedServerName()) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

return request_info.requestedServerName().data();
} else {
requested_server_name = UnspecifiedValueString;
return requested_server_name.data();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

}
};
} else {
throw EnvoyException(fmt::format("Not supported field in RequestInfo: {}", field_name));
}
Expand Down
8 changes: 8 additions & 0 deletions source/common/request_info/request_info_impl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -178,6 +178,12 @@ struct RequestInfoImpl : public RequestInfo {
(*metadata_.mutable_filter_metadata())[name].MergeFrom(value);
};

void setRequestedServerName(const absl::string_view& requested_server_name) override {
requested_server_name_ = requested_server_name;
}

const absl::string_view& requestedServerName() const override { return requested_server_name_; }

const SystemTime start_time_;
const MonotonicTime start_time_monotonic_;

Expand All @@ -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_;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this one's unused.


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_;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's safe, provided 2 things:

  1. 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.

  2. 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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

};

} // namespace RequestInfo
Expand Down
3 changes: 3 additions & 0 deletions source/common/tcp_proxy/tcp_proxy.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

ENVOY_LOG(debug, "TCP:onData(), requestedServerName: {} ",
getRequestInfo().requestedServerName());
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ack, yep that sounds right upon downloading the results

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

return Network::FilterStatus::StopIteration;
}

Expand Down
2 changes: 2 additions & 0 deletions source/extensions/filters/listener/tls_inspector/tls_inspector.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -123,6 +123,8 @@ 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: {}",
cb_->socket().requestedServerName());
} else {
config_->stats().sni_not_found_.inc();
}
Expand Down
14 changes: 14 additions & 0 deletions test/common/access_log/access_log_formatter_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -185,6 +185,20 @@ 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");
// absl::string_view 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));
// }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be enabled?


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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be enabled?

EXPECT_EQ("-", upstream_format.format(header, header, header, request_info));
}
}

TEST(AccessLogFormatterTest, requestHeaderFormatter) {
Expand Down
7 changes: 7 additions & 0 deletions test/common/access_log/test_util.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -154,6 +154,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_ = requested_server_name;
}

const absl::string_view& requestedServerName() const override { return requested_server_name_; }

SystemTime start_time_;
MonotonicTime start_time_monotonic_;

Expand All @@ -176,6 +182,7 @@ class TestRequestInfo : public RequestInfo::RequestInfo {
Network::Address::InstanceConstSharedPtr downstream_remote_address_;
const Router::RouteEntry* route_entry_{};
envoy::api::v2::core::Metadata metadata_{};
absl::string_view requested_server_name_;
};

} // namespace Envoy
5 changes: 5 additions & 0 deletions test/common/request_info/request_info_impl_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(nullptr, request_info.requestedServerName());
absl::string_view sni_name = "stubserver.org";
request_info.setRequestedServerName(sni_name);
EXPECT_EQ(sni_name, request_info.requestedServerName());
}
}

Expand Down
5 changes: 5 additions & 0 deletions test/mocks/request_info/mocks.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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_ = requested_server_name;
}));
ON_CALL(*this, requestedServerName()).WillByDefault(ReturnRef(requested_server_name_));
}

MockRequestInfo::~MockRequestInfo() {}
Expand Down
3 changes: 3 additions & 0 deletions test/mocks/request_info/mocks.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 absl::string_view&());

std::shared_ptr<testing::NiceMock<Upstream::MockHostDescription>> host_{
new testing::NiceMock<Upstream::MockHostDescription>()};
Expand All @@ -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_;
absl::string_view requested_server_name_;
};

} // namespace RequestInfo
Expand Down