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

tracing: add grpc-status and grpc-message to spans #7996

Merged
merged 4 commits into from
Aug 27, 2019
Merged

tracing: add grpc-status and grpc-message to spans #7996

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
35aa35d
tracing: add grpc-status and grpc-message to spans
cgilmour Aug 21, 2019
e0be638
Set error tag for grpc when status not OK
cgilmour Aug 22, 2019
958947f
Tracing docs and release notes entry.
cgilmour Aug 22, 2019
93b43d0
Fix status code and handle trailers-only case.
cgilmour Aug 24, 2019
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
9 changes: 6 additions & 3 deletions docs/root/intro/arch_overview/observability/tracing.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -93,9 +93,12 @@ associated with it. Each span generated by Envoy contains the following data:
* Originating host set via :option:`--service-node`.
* Downstream cluster set via the :ref:`config_http_conn_man_headers_downstream-service-cluster`
header.
* HTTP URL.
* HTTP method.
* HTTP response code.
* HTTP request URL, method, protocol and user-agent.
* Additional HTTP request headers set via :ref:`request_headers_for_tags
<envoy_api_field_config.filter.network.http_connection_manager.v2.HttpConnectionManager.tracing.request_headers_for_tags>`
* HTTP response status code.
* GRPC response status and message (if available).
* An error tag when HTTP status is 5xx or GRPC status is not "OK"
* Tracing system-specific metadata.

The span also includes a name (or operation) which by default is defined as the host of the invoked
Expand Down
1 change: 1 addition & 0 deletions docs/root/intro/version_history.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ Version history
* router check tool: add comprehensive coverage reporting.
* tls: added verification of IP address SAN fields in certificates against configured SANs in the
certificate validation context.
* tracing: added tags for gRPC response status and meesage.
* upstream: added network filter chains to upstream connections, see :ref:`filters<envoy_api_field_Cluster.filters>`.
* upstream: use p2c to select hosts for least-requests load balancers if all host weights are the same, even in cases where weights are not equal to 1.
* zookeeper: parse responses and emit latency stats.
Expand Down
5 changes: 3 additions & 2 deletions source/common/http/conn_manager_impl.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -502,8 +502,9 @@ ConnectionManagerImpl::ActiveStream::~ActiveStream() {
}

if (active_span_) {
Tracing::HttpTracerUtility::finalizeSpan(*active_span_, request_headers_.get(), stream_info_,
*this);
Tracing::HttpTracerUtility::finalizeSpan(*active_span_, request_headers_.get(),
response_headers_.get(), response_trailers_.get(),
stream_info_, *this);
}
if (state_.successful_upgrade_) {
connection_manager_.stats_.named_.downstream_cx_upgrades_active_.dec();
Expand Down
22 changes: 22 additions & 0 deletions source/common/tracing/http_tracer_impl.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
#include "common/common/fmt.h"
#include "common/common/macros.h"
#include "common/common/utility.h"
#include "common/grpc/common.h"
#include "common/http/codes.h"
#include "common/http/header_map_impl.h"
#include "common/http/headers.h"
Expand Down Expand Up @@ -121,6 +122,8 @@ static void annotateVerbose(Span& span, const StreamInfo::StreamInfo& stream_inf
}

void HttpTracerUtility::finalizeSpan(Span& span, const Http::HeaderMap* request_headers,
const Http::HeaderMap* response_headers,
const Http::HeaderMap* response_trailers,
const StreamInfo::StreamInfo& stream_info,
const Config& tracing_config) {
// Pre response data.
Expand Down Expand Up @@ -163,6 +166,25 @@ void HttpTracerUtility::finalizeSpan(Span& span, const Http::HeaderMap* request_
span.setTag(Tracing::Tags::get().ResponseFlags,
StreamInfo::ResponseFlagUtils::toShortString(stream_info));

// GRPC data.
if (response_headers && response_trailers && stream_info.protocol() == Http::Protocol::Http2 &&
Copy link
Member

Choose a reason for hiding this comment

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

Q: Don't you want to handle trailer only (header only) gRPC responses also? These would be useful error cases. cc @lizan

/wait-any

Copy link
Member

Choose a reason for hiding this comment

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

Right this should be extract first of non-null HeaderMap in (response trailers, response headers), I'd not limit the protocol = HTTP2 here since it is also useful cases for grpc_http1_bridge etc, and future gRPC over QUIC(HTTP/3?).

Grpc::Common::hasGrpcContentType(*response_headers)) {
const Http::HeaderEntry* grpc_status_header = response_trailers->GrpcStatus();
if (grpc_status_header) {
span.setTag(Tracing::Tags::get().GrpcStatusCode, grpc_status_header->value().getStringView());
}
const Http::HeaderEntry* grpc_message_header = response_trailers->GrpcMessage();
if (grpc_message_header) {
span.setTag(Tracing::Tags::get().GrpcMessage, grpc_message_header->value().getStringView());
}
absl::optional<Grpc::Status::GrpcStatus> grpc_status_code =
Grpc::Common::getGrpcStatus(*response_trailers);
// Set error tag when status is not OK.
if (grpc_status_code && grpc_status_code.value() != Grpc::Status::GrpcStatus::Ok) {
span.setTag(Tracing::Tags::get().Error, Tracing::Tags::get().True);
}
}
Copy link
Contributor

Choose a reason for hiding this comment

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

Would be good to also set the error tag, as for the async client, if the status is not Ok.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Thanks @objectiser - I've added this.


if (tracing_config.verbose()) {
annotateVerbose(span, stream_info);
}
Expand Down
3 changes: 3 additions & 0 deletions source/common/tracing/http_tracer_impl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@ class TracingTagValues {
// Non-standard tag names.
const std::string DownstreamCluster = "downstream_cluster";
const std::string GrpcStatusCode = "grpc.status_code";
const std::string GrpcMessage = "grpc.message";
const std::string GuidXClientTraceId = "guid:x-client-trace-id";
const std::string GuidXRequestId = "guid:x-request-id";
const std::string HttpProtocol = "http.protocol";
Expand Down Expand Up @@ -101,6 +102,8 @@ class HttpTracerUtility {
* 2) Finish active span.
*/
static void finalizeSpan(Span& span, const Http::HeaderMap* request_headers,
const Http::HeaderMap* response_headers,
const Http::HeaderMap* response_trailers,
const StreamInfo::StreamInfo& stream_info, const Config& tracing_config);

static const std::string IngressOperation;
Expand Down
110 changes: 99 additions & 11 deletions test/common/tracing/http_tracer_impl_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -122,12 +122,14 @@ TEST(HttpConnManFinalizerImpl, OriginalAndLongPath) {
{"x-envoy-original-path", path},
{":method", "GET"},
{"x-forwarded-proto", "http"}};
Http::TestHeaderMapImpl response_headers;
Http::TestHeaderMapImpl response_trailers;
NiceMock<StreamInfo::MockStreamInfo> stream_info;

absl::optional<Http::Protocol> protocol = Http::Protocol::Http2;
EXPECT_CALL(stream_info, bytesReceived()).WillOnce(Return(10));
EXPECT_CALL(stream_info, bytesSent()).WillOnce(Return(11));
EXPECT_CALL(stream_info, protocol()).WillOnce(ReturnPointee(&protocol));
EXPECT_CALL(stream_info, protocol()).WillRepeatedly(ReturnPointee(&protocol));
absl::optional<uint32_t> response_code;
EXPECT_CALL(stream_info, responseCode()).WillRepeatedly(ReturnPointee(&response_code));

Expand All @@ -137,7 +139,8 @@ TEST(HttpConnManFinalizerImpl, OriginalAndLongPath) {
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpProtocol), Eq("HTTP/2")));

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, &request_headers, stream_info, config);
HttpTracerUtility::finalizeSpan(span, &request_headers, &response_headers, &response_trailers,
stream_info, config);
}

TEST(HttpConnManFinalizerImpl, NoGeneratedId) {
Expand All @@ -148,12 +151,14 @@ TEST(HttpConnManFinalizerImpl, NoGeneratedId) {

Http::TestHeaderMapImpl request_headers{
{"x-envoy-original-path", path}, {":method", "GET"}, {"x-forwarded-proto", "http"}};
Http::TestHeaderMapImpl response_headers;
Http::TestHeaderMapImpl response_trailers;
NiceMock<StreamInfo::MockStreamInfo> stream_info;

absl::optional<Http::Protocol> protocol = Http::Protocol::Http2;
EXPECT_CALL(stream_info, bytesReceived()).WillOnce(Return(10));
EXPECT_CALL(stream_info, bytesSent()).WillOnce(Return(11));
EXPECT_CALL(stream_info, protocol()).WillOnce(ReturnPointee(&protocol));
EXPECT_CALL(stream_info, protocol()).WillRepeatedly(ReturnPointee(&protocol));
absl::optional<uint32_t> response_code;
EXPECT_CALL(stream_info, responseCode()).WillRepeatedly(ReturnPointee(&response_code));

Expand All @@ -163,7 +168,8 @@ TEST(HttpConnManFinalizerImpl, NoGeneratedId) {
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpProtocol), Eq("HTTP/2")));

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, &request_headers, stream_info, config);
HttpTracerUtility::finalizeSpan(span, &request_headers, &response_headers, &response_trailers,
stream_info, config);
}

TEST(HttpConnManFinalizerImpl, NullRequestHeaders) {
Expand All @@ -184,7 +190,7 @@ TEST(HttpConnManFinalizerImpl, NullRequestHeaders) {
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().UpstreamCluster), _)).Times(0);

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, nullptr, stream_info, config);
HttpTracerUtility::finalizeSpan(span, nullptr, nullptr, nullptr, stream_info, config);
}

TEST(HttpConnManFinalizerImpl, StreamInfoLogs) {
Expand Down Expand Up @@ -222,7 +228,7 @@ TEST(HttpConnManFinalizerImpl, StreamInfoLogs) {

NiceMock<MockConfig> config;
EXPECT_CALL(config, verbose).WillOnce(Return(true));
HttpTracerUtility::finalizeSpan(span, nullptr, stream_info, config);
HttpTracerUtility::finalizeSpan(span, nullptr, nullptr, nullptr, stream_info, config);
}

TEST(HttpConnManFinalizerImpl, UpstreamClusterTagSet) {
Expand All @@ -244,7 +250,7 @@ TEST(HttpConnManFinalizerImpl, UpstreamClusterTagSet) {
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().RequestSize), Eq("10")));

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, nullptr, stream_info, config);
HttpTracerUtility::finalizeSpan(span, nullptr, nullptr, nullptr, stream_info, config);
}

TEST(HttpConnManFinalizerImpl, SpanOptionalHeaders) {
Expand All @@ -254,11 +260,13 @@ TEST(HttpConnManFinalizerImpl, SpanOptionalHeaders) {
{":path", "/test"},
{":method", "GET"},
{"x-forwarded-proto", "https"}};
Http::TestHeaderMapImpl response_headers;
Http::TestHeaderMapImpl response_trailers;
NiceMock<StreamInfo::MockStreamInfo> stream_info;

absl::optional<Http::Protocol> protocol = Http::Protocol::Http10;
EXPECT_CALL(stream_info, bytesReceived()).WillOnce(Return(10));
EXPECT_CALL(stream_info, protocol()).WillOnce(ReturnPointee(&protocol));
EXPECT_CALL(stream_info, protocol()).WillRepeatedly(ReturnPointee(&protocol));
const std::string service_node = "i-453";

// Check that span is populated correctly.
Expand All @@ -282,7 +290,8 @@ TEST(HttpConnManFinalizerImpl, SpanOptionalHeaders) {
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().UpstreamCluster), _)).Times(0);

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, &request_headers, stream_info, config);
HttpTracerUtility::finalizeSpan(span, &request_headers, &response_headers, &response_trailers,
stream_info, config);
}

TEST(HttpConnManFinalizerImpl, SpanPopulatedFailureResponse) {
Expand All @@ -291,6 +300,8 @@ TEST(HttpConnManFinalizerImpl, SpanPopulatedFailureResponse) {
{":path", "/test"},
{":method", "GET"},
{"x-forwarded-proto", "http"}};
Http::TestHeaderMapImpl response_headers;
Http::TestHeaderMapImpl response_trailers;
NiceMock<StreamInfo::MockStreamInfo> stream_info;

request_headers.insertHost().value(std::string("api"));
Expand All @@ -299,7 +310,7 @@ TEST(HttpConnManFinalizerImpl, SpanPopulatedFailureResponse) {
request_headers.insertClientTraceId().value(std::string("client_trace_id"));

absl::optional<Http::Protocol> protocol = Http::Protocol::Http10;
EXPECT_CALL(stream_info, protocol()).WillOnce(ReturnPointee(&protocol));
EXPECT_CALL(stream_info, protocol()).WillRepeatedly(ReturnPointee(&protocol));
EXPECT_CALL(stream_info, bytesReceived()).WillOnce(Return(10));
const std::string service_node = "i-453";

Expand Down Expand Up @@ -339,7 +350,80 @@ TEST(HttpConnManFinalizerImpl, SpanPopulatedFailureResponse) {
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().ResponseFlags), Eq("UT")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().UpstreamCluster), _)).Times(0);

HttpTracerUtility::finalizeSpan(span, &request_headers, stream_info, config);
HttpTracerUtility::finalizeSpan(span, &request_headers, &response_headers, &response_trailers,
stream_info, config);
}

TEST(HttpConnManFinalizerImpl, GrpcOkStatus) {
const std::string path_prefix = "http://";
NiceMock<MockSpan> span;

Http::TestHeaderMapImpl request_headers{{":method", "POST"},
{":scheme", "http"},
{":path", "/pb.Foo/Bar"},
{":authority", "example.com:80"},
{"content-type", "application/grpc"},
{"te", "trailers"}};

Http::TestHeaderMapImpl response_headers{{":status", "200"},
{"content-type", "application/grpc"}};
Http::TestHeaderMapImpl response_trailers{{"grpc-status", "0"}, {"grpc-message", ""}};
NiceMock<StreamInfo::MockStreamInfo> stream_info;

absl::optional<Http::Protocol> protocol = Http::Protocol::Http2;
absl::optional<uint32_t> response_code(200);
EXPECT_CALL(stream_info, responseCode()).WillRepeatedly(ReturnPointee(&response_code));
EXPECT_CALL(stream_info, bytesReceived()).WillOnce(Return(10));
EXPECT_CALL(stream_info, bytesSent()).WillOnce(Return(11));
EXPECT_CALL(stream_info, protocol()).WillRepeatedly(ReturnPointee(&protocol));

EXPECT_CALL(span, setTag(_, _)).Times(testing::AnyNumber());
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpMethod), Eq("POST")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpProtocol), Eq("HTTP/2")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpStatusCode), Eq("200")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().GrpcStatusCode), Eq("0")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().GrpcMessage), Eq("")));

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, &request_headers, &response_headers, &response_trailers,
stream_info, config);
}

TEST(HttpConnManFinalizerImpl, GrpcError) {
Copy link
Member

Choose a reason for hiding this comment

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

add a test for trailer-only case too.

const std::string path_prefix = "http://";
NiceMock<MockSpan> span;

Http::TestHeaderMapImpl request_headers{{":method", "POST"},
{":scheme", "http"},
{":path", "/pb.Foo/Bar"},
{":authority", "example.com:80"},
{"content-type", "application/grpc"},
{"te", "trailers"}};

Http::TestHeaderMapImpl response_headers{{":status", "403"},
Copy link
Member

Choose a reason for hiding this comment

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

:status is usually 200 even grpc-status is not 0.

{"content-type", "application/grpc"}};
Http::TestHeaderMapImpl response_trailers{{"grpc-status", "7"},
{"grpc-message", "permission denied"}};
NiceMock<StreamInfo::MockStreamInfo> stream_info;

absl::optional<Http::Protocol> protocol = Http::Protocol::Http2;
absl::optional<uint32_t> response_code(403);
EXPECT_CALL(stream_info, responseCode()).WillRepeatedly(ReturnPointee(&response_code));
EXPECT_CALL(stream_info, bytesReceived()).WillOnce(Return(10));
EXPECT_CALL(stream_info, bytesSent()).WillOnce(Return(11));
EXPECT_CALL(stream_info, protocol()).WillRepeatedly(ReturnPointee(&protocol));

EXPECT_CALL(span, setTag(_, _)).Times(testing::AnyNumber());
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().Error), Eq(Tracing::Tags::get().True)));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpMethod), Eq("POST")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpProtocol), Eq("HTTP/2")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().HttpStatusCode), Eq("403")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().GrpcStatusCode), Eq("7")));
EXPECT_CALL(span, setTag(Eq(Tracing::Tags::get().GrpcMessage), Eq("permission denied")));

NiceMock<MockConfig> config;
HttpTracerUtility::finalizeSpan(span, &request_headers, &response_headers, &response_trailers,
stream_info, config);
}

TEST(HttpTracerUtilityTest, operationTypeToString) {
Expand All @@ -352,6 +436,8 @@ TEST(HttpNullTracerTest, BasicFunctionality) {
MockConfig config;
StreamInfo::MockStreamInfo stream_info;
Http::TestHeaderMapImpl request_headers;
Http::TestHeaderMapImpl response_headers;
Http::TestHeaderMapImpl response_trailers;

SpanPtr span_ptr =
null_tracer.startSpan(config, request_headers, stream_info, {Reason::Sampling, true});
Expand All @@ -374,6 +460,8 @@ class HttpTracerImplTest : public testing::Test {

Http::TestHeaderMapImpl request_headers_{
{":path", "/"}, {":method", "GET"}, {"x-request-id", "foo"}, {":authority", "test"}};
Http::TestHeaderMapImpl response_headers;
Http::TestHeaderMapImpl response_trailers;
StreamInfo::MockStreamInfo stream_info_;
NiceMock<LocalInfo::MockLocalInfo> local_info_;
MockConfig config_;
Expand Down