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 all 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
26 changes: 26 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 @@ -81,6 +82,22 @@ Decision HttpTracerUtility::isTracing(const StreamInfo::StreamInfo& stream_info,
NOT_REACHED_GCOVR_EXCL_LINE;
}

static void addGrpcTags(Span& span, const Http::HeaderMap& headers) {
const Http::HeaderEntry* grpc_status_header = headers.GrpcStatus();
if (grpc_status_header) {
span.setTag(Tracing::Tags::get().GrpcStatusCode, grpc_status_header->value().getStringView());
}
const Http::HeaderEntry* grpc_message_header = headers.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(headers);
// 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);
}
}

static void annotateVerbose(Span& span, const StreamInfo::StreamInfo& stream_info) {
const auto start_time = stream_info.startTime();
if (stream_info.lastDownstreamRxByteReceived()) {
Expand Down Expand Up @@ -121,6 +138,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 +182,13 @@ void HttpTracerUtility::finalizeSpan(Span& span, const Http::HeaderMap* request_
span.setTag(Tracing::Tags::get().ResponseFlags,
StreamInfo::ResponseFlagUtils::toShortString(stream_info));

// GRPC data.
if (response_trailers && response_trailers->GrpcStatus() != nullptr) {
addGrpcTags(span, *response_trailers);
} else if (response_headers && response_headers->GrpcStatus() != nullptr) {
addGrpcTags(span, *response_headers);
}
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
148 changes: 137 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,118 @@ 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, GrpcErrorTag) {
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", "7"},
{"grpc-message", "permission denied"}};
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().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("200")));
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(HttpConnManFinalizerImpl, GrpcTrailersOnly) {
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"},
{"grpc-status", "7"},
{"grpc-message", "permission denied"}};
Http::TestHeaderMapImpl response_trailers;
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().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("200")));
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 +474,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 +498,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