diff --git a/doc/environment_variables.md b/doc/environment_variables.md index aef14a9842c..e79c390c9a3 100644 --- a/doc/environment_variables.md +++ b/doc/environment_variables.md @@ -49,6 +49,7 @@ some configuration as environment variables that can be set. - cares_resolver - traces operations of the c-ares based DNS resolver - cares_address_sorting - traces operations of the c-ares based DNS resolver's resolved address sorter + - cds_lb - traces cds LB policy - channel - traces operations on the C core channel stack - client_channel_call - traces client channel call batch activity - client_channel_routing - traces client channel call routing, including @@ -77,11 +78,15 @@ some configuration as environment variables that can be set. - server_channel - lightweight trace of significant server channel events - secure_endpoint - traces bytes flowing through encrypted channels - subchannel - traces the connectivity state of subchannel + - subchannel_pool - traces subchannel pool - timer - timers (alarms) in the grpc internals - timer_check - more detailed trace of timer logic in grpc internals - transport_security - traces metadata about secure channel establishment - tcp - traces bytes in and out of a channel - tsi - traces tsi transport security + - xds_client - traces xds client + - xds_lb - traces xds LB policy + - xds_resolver - traces xds resolver The following tracers will only run in binaries built in DEBUG mode. This is accomplished by invoking `CONFIG=dbg make ` diff --git a/src/core/ext/filters/client_channel/lb_policy/xds/cds.cc b/src/core/ext/filters/client_channel/lb_policy/xds/cds.cc index 41c031b97d8..5e7d34823fb 100644 --- a/src/core/ext/filters/client_channel/lb_policy/xds/cds.cc +++ b/src/core/ext/filters/client_channel/lb_policy/xds/cds.cc @@ -113,8 +113,14 @@ class CdsLb : public LoadBalancingPolicy { void CdsLb::ClusterWatcher::OnClusterChanged(XdsApi::CdsUpdate cluster_data) { if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { - gpr_log(GPR_INFO, "[cdslb %p] received CDS update from xds client", - parent_.get()); + gpr_log(GPR_INFO, + "[cdslb %p] received CDS update from xds client %p: " + "eds_service_name=%s lrs_load_reporting_server_name=%s", + parent_.get(), parent_->xds_client_.get(), + cluster_data.eds_service_name.c_str(), + cluster_data.lrs_load_reporting_server_name.has_value() + ? cluster_data.lrs_load_reporting_server_name.value().c_str() + : "(unset)"); } // Construct config for child policy. Json::Object child_config = { @@ -152,9 +158,18 @@ void CdsLb::ClusterWatcher::OnClusterChanged(XdsApi::CdsUpdate cluster_data) { parent_->child_policy_ = LoadBalancingPolicyRegistry::CreateLoadBalancingPolicy( "xds_experimental", std::move(args)); + if (parent_->child_policy_ == nullptr) { + OnError(GRPC_ERROR_CREATE_FROM_STATIC_STRING( + "failed to create xds_experimental child policy")); + return; + } grpc_pollset_set_add_pollset_set( parent_->child_policy_->interested_parties(), parent_->interested_parties()); + if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { + gpr_log(GPR_INFO, "[cdslb %p] created child policy xds_experimental (%p)", + parent_.get(), parent_->child_policy_.get()); + } } // Update child policy. UpdateArgs args; @@ -220,9 +235,9 @@ void CdsLb::Helper::AddTraceEvent(TraceSeverity severity, StringView message) { CdsLb::CdsLb(Args args) : LoadBalancingPolicy(std::move(args)), xds_client_(XdsClient::GetFromChannelArgs(*args.args)) { - if (xds_client_ != nullptr && GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { - gpr_log(GPR_INFO, "[cdslb %p] Using xds client %p from channel", this, - xds_client_.get()); + if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { + gpr_log(GPR_INFO, "[cdslb %p] created -- using xds client %p from channel", + this, xds_client_.get()); } } @@ -245,6 +260,10 @@ void CdsLb::ShutdownLocked() { } if (xds_client_ != nullptr) { if (cluster_watcher_ != nullptr) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { + gpr_log(GPR_INFO, "[cdslb %p] cancelling watch for cluster %s", this, + config_->cluster().c_str()); + } xds_client_->CancelClusterDataWatch( StringView(config_->cluster().c_str()), cluster_watcher_); } @@ -257,12 +276,13 @@ void CdsLb::ResetBackoffLocked() { } void CdsLb::UpdateLocked(UpdateArgs args) { - if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { - gpr_log(GPR_INFO, "[cdslb %p] received update", this); - } // Update config. auto old_config = std::move(config_); config_ = std::move(args.config); + if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { + gpr_log(GPR_INFO, "[cdslb %p] received update: cluster=%s", this, + config_->cluster().c_str()); + } // Update args. grpc_channel_args_destroy(args_); args_ = args.args; @@ -270,9 +290,17 @@ void CdsLb::UpdateLocked(UpdateArgs args) { // If cluster name changed, cancel watcher and restart. if (old_config == nullptr || old_config->cluster() != config_->cluster()) { if (old_config != nullptr) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { + gpr_log(GPR_INFO, "[cdslb %p] cancelling watch for cluster %s", this, + old_config->cluster().c_str()); + } xds_client_->CancelClusterDataWatch( StringView(old_config->cluster().c_str()), cluster_watcher_); } + if (GRPC_TRACE_FLAG_ENABLED(grpc_cds_lb_trace)) { + gpr_log(GPR_INFO, "[cdslb %p] starting watch for cluster %s", this, + config_->cluster().c_str()); + } auto watcher = absl::make_unique(Ref()); cluster_watcher_ = watcher.get(); xds_client_->WatchClusterData(StringView(config_->cluster().c_str()), diff --git a/src/core/ext/filters/client_channel/lb_policy/xds/xds.cc b/src/core/ext/filters/client_channel/lb_policy/xds/xds.cc index 4e16bb50214..5277f22a32a 100644 --- a/src/core/ext/filters/client_channel/lb_policy/xds/xds.cc +++ b/src/core/ext/filters/client_channel/lb_policy/xds/xds.cc @@ -69,7 +69,7 @@ namespace grpc_core { -TraceFlag grpc_lb_xds_trace(false, "xds"); +TraceFlag grpc_lb_xds_trace(false, "xds_lb"); namespace { @@ -619,6 +619,9 @@ class XdsLb::EndpointWatcher : public XdsClient::EndpointWatcherInterface { if (strstr(grpc_error_string(error), "xds call failed")) { xds_policy_->channel_control_helper()->RequestReresolution(); } + } else if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] xds watcher reported error (ignoring): %s", + xds_policy_.get(), grpc_error_string(error)); } GRPC_ERROR_UNREF(error); } @@ -643,9 +646,8 @@ XdsLb::XdsLb(Args args) locality_map_failover_timeout_ms_(grpc_channel_args_find_integer( args.args, GRPC_ARG_XDS_FAILOVER_TIMEOUT_MS, {GRPC_XDS_DEFAULT_FAILOVER_TIMEOUT_MS, 0, INT_MAX})) { - if (xds_client_from_channel_ != nullptr && - GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { - gpr_log(GPR_INFO, "[xdslb %p] Using xds client %p from channel", this, + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] created -- xds client from channel: %p", this, xds_client_from_channel_.get()); } // Record server name. @@ -687,6 +689,10 @@ void XdsLb::ShutdownLocked() { // destroying the Xds client leading to a situation where the Xds lb policy is // never destroyed. if (xds_client_from_channel_ != nullptr) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] cancelling watch for %s", this, + eds_service_name()); + } xds_client()->CancelEndpointDataWatch(StringView(eds_service_name()), endpoint_watcher_); xds_client_from_channel_.reset(); @@ -781,9 +787,17 @@ void XdsLb::UpdateLocked(UpdateArgs args) { if (is_initial_update || strcmp(old_eds_service_name, eds_service_name()) != 0) { if (!is_initial_update) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] cancelling watch for %s", this, + old_eds_service_name); + } xds_client()->CancelEndpointDataWatch(StringView(old_eds_service_name), endpoint_watcher_); } + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] starting watch for %s", this, + eds_service_name()); + } auto watcher = absl::make_unique( Ref(DEBUG_LOCATION, "EndpointWatcher")); endpoint_watcher_ = watcher.get(); @@ -1071,6 +1085,9 @@ void XdsLb::LocalityMap::ResetBackoffLocked() { } void XdsLb::LocalityMap::UpdateXdsPickerLocked() { + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] constructing new picker", xds_policy()); + } // Construct a new xds picker which maintains a map of all locality pickers // that are ready. Each locality is represented by a portion of the range // proportional to its weight, such that the total range is the sum of the @@ -1086,6 +1103,11 @@ void XdsLb::LocalityMap::UpdateXdsPickerLocked() { end += locality->weight(); picker_list.push_back( std::make_pair(end, locality->GetLoadReportingPicker())); + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, "[xdslb %p] locality=%s weight=%d picker=%p", + xds_policy(), locality_name->AsHumanReadableString(), + locality->weight(), picker_list.back().second.get()); + } } xds_policy()->channel_control_helper()->UpdateState( GRPC_CHANNEL_READY, @@ -1492,6 +1514,12 @@ XdsLb::LocalityMap::Locality::Helper::CreateSubchannel( void XdsLb::LocalityMap::Locality::Helper::UpdateState( grpc_connectivity_state state, std::unique_ptr picker) { if (locality_->xds_policy()->shutting_down_) return; + if (GRPC_TRACE_FLAG_ENABLED(grpc_lb_xds_trace)) { + gpr_log(GPR_INFO, + "[xdslb %p helper %p] child policy handler %p reports state=%s", + locality_->xds_policy(), this, locality_->child_policy_.get(), + ConnectivityStateName(state)); + } // Cache the state and picker in the locality. locality_->connectivity_state_ = state; locality_->picker_wrapper_ = diff --git a/src/core/ext/filters/client_channel/resolver/xds/xds_resolver.cc b/src/core/ext/filters/client_channel/resolver/xds/xds_resolver.cc index 8b7354f8621..95fc1535689 100644 --- a/src/core/ext/filters/client_channel/resolver/xds/xds_resolver.cc +++ b/src/core/ext/filters/client_channel/resolver/xds/xds_resolver.cc @@ -24,6 +24,8 @@ namespace grpc_core { +TraceFlag grpc_xds_resolver_trace(false, "xds_resolver"); + namespace { // @@ -38,14 +40,28 @@ class XdsResolver : public Resolver { interested_parties_(args.pollset_set) { char* path = args.uri->path; if (path[0] == '/') ++path; - server_name_.reset(gpr_strdup(path)); + server_name_ = path; + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_resolver_trace)) { + gpr_log(GPR_INFO, "[xds_resolver %p] created for server name %s", this, + server_name_.c_str()); + } } - ~XdsResolver() override { grpc_channel_args_destroy(args_); } + ~XdsResolver() override { + grpc_channel_args_destroy(args_); + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_resolver_trace)) { + gpr_log(GPR_INFO, "[xds_resolver %p] destroyed", this); + } + } void StartLocked() override; - void ShutdownLocked() override { xds_client_.reset(); } + void ShutdownLocked() override { + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_resolver_trace)) { + gpr_log(GPR_INFO, "[xds_resolver %p] shutting down", this); + } + xds_client_.reset(); + } private: class ServiceConfigWatcher : public XdsClient::ServiceConfigWatcherInterface { @@ -60,7 +76,7 @@ class XdsResolver : public Resolver { RefCountedPtr resolver_; }; - grpc_core::UniquePtr server_name_; + std::string server_name_; const grpc_channel_args* args_; grpc_pollset_set* interested_parties_; OrphanablePtr xds_client_; @@ -69,6 +85,10 @@ class XdsResolver : public Resolver { void XdsResolver::ServiceConfigWatcher::OnServiceConfigChanged( RefCountedPtr service_config) { if (resolver_->xds_client_ == nullptr) return; + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_resolver_trace)) { + gpr_log(GPR_INFO, "[xds_resolver %p] received updated service config: %s", + resolver_.get(), service_config->json_string().c_str()); + } grpc_arg xds_client_arg = resolver_->xds_client_->MakeChannelArg(); Result result; result.args = @@ -79,6 +99,8 @@ void XdsResolver::ServiceConfigWatcher::OnServiceConfigChanged( void XdsResolver::ServiceConfigWatcher::OnError(grpc_error* error) { if (resolver_->xds_client_ == nullptr) return; + gpr_log(GPR_ERROR, "[xds_resolver %p] received error: %s", resolver_.get(), + grpc_error_string(error)); grpc_arg xds_client_arg = resolver_->xds_client_->MakeChannelArg(); Result result; result.args = @@ -90,7 +112,7 @@ void XdsResolver::ServiceConfigWatcher::OnError(grpc_error* error) { void XdsResolver::StartLocked() { grpc_error* error = GRPC_ERROR_NONE; xds_client_ = MakeOrphanable( - combiner(), interested_parties_, StringView(server_name_.get()), + combiner(), interested_parties_, server_name_, absl::make_unique(Ref()), *args_, &error); if (error != GRPC_ERROR_NONE) { gpr_log(GPR_ERROR, diff --git a/src/core/ext/filters/client_channel/xds/xds_api.cc b/src/core/ext/filters/client_channel/xds/xds_api.cc index e2628cb3f57..9dc6d39ce66 100644 --- a/src/core/ext/filters/client_channel/xds/xds_api.cc +++ b/src/core/ext/filters/client_channel/xds/xds_api.cc @@ -23,6 +23,7 @@ #include #include "absl/strings/str_cat.h" +#include "absl/strings/str_join.h" #include #include @@ -125,8 +126,11 @@ const char* XdsApi::kCdsTypeUrl = "type.googleapis.com/envoy.api.v2.Cluster"; const char* XdsApi::kEdsTypeUrl = "type.googleapis.com/envoy.api.v2.ClusterLoadAssignment"; -XdsApi::XdsApi(const XdsBootstrap::Node* node) - : node_(node), +XdsApi::XdsApi(XdsClient* client, TraceFlag* tracer, + const XdsBootstrap::Node* node) + : client_(client), + tracer_(tracer), + node_(node), build_version_(absl::StrCat("gRPC C-core ", GPR_PLATFORM_STRING, " ", grpc_version_string())), user_agent_name_(absl::StrCat("gRPC C-core ", GPR_PLATFORM_STRING)) {} @@ -289,6 +293,162 @@ envoy_api_v2_DiscoveryRequest* CreateDiscoveryRequest( return request; } +inline absl::string_view UpbStringToAbsl(const upb_strview& str) { + return absl::string_view(str.data, str.size); +} + +inline void AddStringField(const char* name, const upb_strview& value, + std::vector* fields, + bool add_if_empty = false) { + if (value.size > 0 || add_if_empty) { + fields->emplace_back( + absl::StrCat(name, ": \"", UpbStringToAbsl(value), "\"")); + } +} + +inline void AddLocalityField(int indent_level, + const envoy_api_v2_core_Locality* locality, + std::vector* fields) { + std::string indent = + absl::StrJoin(std::vector(indent_level, " "), ""); + // region + std::string field = absl::StrCat(indent, "region"); + AddStringField(field.c_str(), envoy_api_v2_core_Locality_region(locality), + fields); + // zone + field = absl::StrCat(indent, "zone"); + AddStringField(field.c_str(), envoy_api_v2_core_Locality_zone(locality), + fields); + // sub_zone + field = absl::StrCat(indent, "sub_zone"); + AddStringField(field.c_str(), envoy_api_v2_core_Locality_sub_zone(locality), + fields); +} + +void AddNodeLogFields(const envoy_api_v2_core_Node* node, + std::vector* fields) { + fields->emplace_back("node {"); + // id + AddStringField(" id", envoy_api_v2_core_Node_id(node), fields); + // metadata + const google_protobuf_Struct* metadata = + envoy_api_v2_core_Node_metadata(node); + if (metadata != nullptr) { + fields->emplace_back(" metadata {"); + size_t num_entries; + const google_protobuf_Struct_FieldsEntry* const* entries = + google_protobuf_Struct_fields(metadata, &num_entries); + for (size_t i = 0; i < num_entries; ++i) { + fields->emplace_back(" field {"); + // key + AddStringField(" key", + google_protobuf_Struct_FieldsEntry_key(entries[i]), + fields); + // value + const google_protobuf_Value* value = + google_protobuf_Struct_FieldsEntry_value(entries[i]); + if (value != nullptr) { + std::string value_str; + if (google_protobuf_Value_has_string_value(value)) { + value_str = absl::StrCat( + "string_value: \"", + UpbStringToAbsl(google_protobuf_Value_string_value(value)), "\""); + } else if (google_protobuf_Value_has_null_value(value)) { + value_str = "null_value: NULL_VALUE"; + } else if (google_protobuf_Value_has_number_value(value)) { + value_str = absl::StrCat("double_value: ", + google_protobuf_Value_number_value(value)); + } else if (google_protobuf_Value_has_bool_value(value)) { + value_str = absl::StrCat("bool_value: ", + google_protobuf_Value_bool_value(value)); + } else if (google_protobuf_Value_has_struct_value(value)) { + value_str = "struct_value: "; + } else if (google_protobuf_Value_has_list_value(value)) { + value_str = "list_value: "; + } else { + value_str = ""; + } + fields->emplace_back(absl::StrCat(" value { ", value_str, " }")); + } + fields->emplace_back(" }"); + } + fields->emplace_back(" }"); + } + // locality + const envoy_api_v2_core_Locality* locality = + envoy_api_v2_core_Node_locality(node); + if (locality != nullptr) { + fields->emplace_back(" locality {"); + AddLocalityField(2, locality, fields); + fields->emplace_back(" }"); + } + // build_version + AddStringField(" build_version", envoy_api_v2_core_Node_build_version(node), + fields); + // user_agent_name + AddStringField(" user_agent_name", + envoy_api_v2_core_Node_user_agent_name(node), fields); + // user_agent_version + AddStringField(" user_agent_version", + envoy_api_v2_core_Node_user_agent_version(node), fields); + // client_features + size_t num_client_features; + const upb_strview* client_features = + envoy_api_v2_core_Node_client_features(node, &num_client_features); + for (size_t i = 0; i < num_client_features; ++i) { + AddStringField(" client_features", client_features[i], fields); + } + fields->emplace_back("}"); +} + +void MaybeLogDiscoveryRequest(XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_DiscoveryRequest* request) { + if (GRPC_TRACE_FLAG_ENABLED(*tracer) && + gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { + // TODO(roth): When we can upgrade upb, use upb textformat code to dump + // the raw proto instead of doing this manually. + std::vector fields; + // version_info + AddStringField("version_info", + envoy_api_v2_DiscoveryRequest_version_info(request), + &fields); + // node + const envoy_api_v2_core_Node* node = + envoy_api_v2_DiscoveryRequest_node(request); + if (node != nullptr) AddNodeLogFields(node, &fields); + // resource_names + size_t num_resource_names; + const upb_strview* resource_names = + envoy_api_v2_DiscoveryRequest_resource_names(request, + &num_resource_names); + for (size_t i = 0; i < num_resource_names; ++i) { + AddStringField("resource_names", resource_names[i], &fields); + } + // type_url + AddStringField("type_url", envoy_api_v2_DiscoveryRequest_type_url(request), + &fields); + // response_nonce + AddStringField("response_nonce", + envoy_api_v2_DiscoveryRequest_response_nonce(request), + &fields); + // error_detail + const struct google_rpc_Status* error_detail = + envoy_api_v2_DiscoveryRequest_error_detail(request); + if (error_detail != nullptr) { + fields.emplace_back("error_detail {"); + // code + int32_t code = google_rpc_Status_code(error_detail); + if (code != 0) fields.emplace_back(absl::StrCat(" code: ", code)); + // message + AddStringField(" message", google_rpc_Status_message(error_detail), + &fields); + fields.emplace_back("}"); + } + gpr_log(GPR_DEBUG, "[xds_client %p] constructed ADS request: %s", client, + absl::StrJoin(fields, "\n").c_str()); + } +} + grpc_slice SerializeDiscoveryRequest(upb_arena* arena, envoy_api_v2_DiscoveryRequest* request) { size_t output_length; @@ -305,6 +465,7 @@ grpc_slice XdsApi::CreateUnsupportedTypeNackRequest(const std::string& type_url, upb::Arena arena; envoy_api_v2_DiscoveryRequest* request = CreateDiscoveryRequest( arena.ptr(), type_url.c_str(), /*version=*/"", nonce, error); + MaybeLogDiscoveryRequest(client_, tracer_, request); return SerializeDiscoveryRequest(arena.ptr(), request); } @@ -326,6 +487,7 @@ grpc_slice XdsApi::CreateLdsRequest(const std::string& server_name, envoy_api_v2_DiscoveryRequest_add_resource_names( request, upb_strview_make(server_name.data(), server_name.size()), arena.ptr()); + MaybeLogDiscoveryRequest(client_, tracer_, request); return SerializeDiscoveryRequest(arena.ptr(), request); } @@ -348,6 +510,7 @@ grpc_slice XdsApi::CreateRdsRequest(const std::string& route_config_name, request, upb_strview_make(route_config_name.data(), route_config_name.size()), arena.ptr()); + MaybeLogDiscoveryRequest(client_, tracer_, request); return SerializeDiscoveryRequest(arena.ptr(), request); } @@ -371,6 +534,7 @@ grpc_slice XdsApi::CreateCdsRequest(const std::set& cluster_names, request, upb_strview_make(cluster_name.data(), cluster_name.size()), arena.ptr()); } + MaybeLogDiscoveryRequest(client_, tracer_, request); return SerializeDiscoveryRequest(arena.ptr(), request); } @@ -394,11 +558,347 @@ grpc_slice XdsApi::CreateEdsRequest( upb_strview_make(eds_service_name.data(), eds_service_name.size()), arena.ptr()); } + MaybeLogDiscoveryRequest(client_, tracer_, request); return SerializeDiscoveryRequest(arena.ptr(), request); } namespace { +void MaybeLogDiscoveryResponse(XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_DiscoveryResponse* response) { + if (GRPC_TRACE_FLAG_ENABLED(*tracer) && + gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { + // TODO(roth): When we can upgrade upb, use upb textformat code to dump + // the raw proto instead of doing this manually. + std::vector fields; + // version_info + AddStringField("version_info", + envoy_api_v2_DiscoveryResponse_version_info(response), + &fields); + // resources + size_t num_resources; + envoy_api_v2_DiscoveryResponse_resources(response, &num_resources); + fields.emplace_back( + absl::StrCat("resources: <", num_resources, " element(s)>")); + // type_url + AddStringField("type_url", + envoy_api_v2_DiscoveryResponse_type_url(response), &fields); + // nonce + AddStringField("nonce", envoy_api_v2_DiscoveryResponse_nonce(response), + &fields); + gpr_log(GPR_DEBUG, "[xds_client %p] received response: %s", client, + absl::StrJoin(fields, "\n").c_str()); + } +} + +void MaybeLogRouteConfiguration( + XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_RouteConfiguration* route_config) { + if (GRPC_TRACE_FLAG_ENABLED(*tracer) && + gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { + // TODO(roth): When we can upgrade upb, use upb textformat code to dump + // the raw proto instead of doing this manually. + std::vector fields; + // name + AddStringField("name", envoy_api_v2_RouteConfiguration_name(route_config), + &fields); + // virtual_hosts + size_t num_virtual_hosts; + const envoy_api_v2_route_VirtualHost* const* virtual_hosts = + envoy_api_v2_RouteConfiguration_virtual_hosts(route_config, + &num_virtual_hosts); + for (size_t i = 0; i < num_virtual_hosts; ++i) { + const auto* virtual_host = virtual_hosts[i]; + fields.push_back("virtual_hosts {"); + // name + AddStringField( + " name", envoy_api_v2_route_VirtualHost_name(virtual_host), &fields); + // domains + size_t num_domains; + const upb_strview* const domains = + envoy_api_v2_route_VirtualHost_domains(virtual_host, &num_domains); + for (size_t j = 0; j < num_domains; ++j) { + AddStringField(" domains", domains[j], &fields); + } + // routes + size_t num_routes; + const envoy_api_v2_route_Route* const* routes = + envoy_api_v2_route_VirtualHost_routes(virtual_host, &num_routes); + for (size_t j = 0; j < num_routes; ++j) { + const auto* route = routes[j]; + fields.push_back(" route {"); + // name + AddStringField(" name", envoy_api_v2_route_Route_name(route), + &fields); + // match + const envoy_api_v2_route_RouteMatch* match = + envoy_api_v2_route_Route_match(route); + if (match != nullptr) { + fields.emplace_back(" match {"); + // path matching + if (envoy_api_v2_route_RouteMatch_has_prefix(match)) { + AddStringField(" prefix", + envoy_api_v2_route_RouteMatch_prefix(match), &fields, + /*add_if_empty=*/true); + } else if (envoy_api_v2_route_RouteMatch_has_path(match)) { + AddStringField(" path", + envoy_api_v2_route_RouteMatch_path(match), &fields, + /*add_if_empty=*/true); + } else if (envoy_api_v2_route_RouteMatch_has_regex(match)) { + AddStringField(" regex", + envoy_api_v2_route_RouteMatch_regex(match), &fields, + /*add_if_empty=*/true); + } else if (envoy_api_v2_route_RouteMatch_has_safe_regex(match)) { + fields.emplace_back(" safe_regex: "); + } else { + fields.emplace_back(" "); + } + // header matching + size_t num_headers; + envoy_api_v2_route_RouteMatch_headers(match, &num_headers); + if (num_headers > 0) { + fields.emplace_back( + absl::StrCat(" headers: <", num_headers, " element(s)>")); + } + fields.emplace_back(" }"); + } + // action + if (envoy_api_v2_route_Route_has_route(route)) { + const envoy_api_v2_route_RouteAction* action = + envoy_api_v2_route_Route_route(route); + fields.emplace_back(" route {"); + if (envoy_api_v2_route_RouteAction_has_cluster(action)) { + AddStringField(" cluster", + envoy_api_v2_route_RouteAction_cluster(action), + &fields); + } else if (envoy_api_v2_route_RouteAction_has_cluster_header( + action)) { + AddStringField( + " cluster_header", + envoy_api_v2_route_RouteAction_cluster_header(action), &fields); + } else if (envoy_api_v2_route_RouteAction_has_weighted_clusters( + action)) { + fields.emplace_back(" weighted_clusters: "); + } + fields.emplace_back(" }"); + } else if (envoy_api_v2_route_Route_has_redirect(route)) { + fields.emplace_back(" redirect: "); + } else if (envoy_api_v2_route_Route_has_direct_response(route)) { + fields.emplace_back(" direct_response: "); + } else if (envoy_api_v2_route_Route_has_filter_action(route)) { + fields.emplace_back(" filter_action: "); + } + fields.push_back(" }"); + } + fields.push_back("}"); + } + gpr_log(GPR_DEBUG, "[xds_client %p] RouteConfiguration: %s", client, + absl::StrJoin(fields, "\n").c_str()); + } +} + +void MaybeLogCluster(XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_Cluster* cluster) { + if (GRPC_TRACE_FLAG_ENABLED(*tracer) && + gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { + // TODO(roth): When we can upgrade upb, use upb textformat code to dump + // the raw proto instead of doing this manually. + std::vector fields; + // name + AddStringField("name", envoy_api_v2_Cluster_name(cluster), &fields); + // type + if (envoy_api_v2_Cluster_has_type(cluster)) { + fields.emplace_back( + absl::StrCat("type: ", envoy_api_v2_Cluster_type(cluster))); + } else if (envoy_api_v2_Cluster_has_cluster_type(cluster)) { + fields.emplace_back("cluster_type: "); + } else { + fields.emplace_back(""); + } + // eds_cluster_config + const envoy_api_v2_Cluster_EdsClusterConfig* eds_cluster_config = + envoy_api_v2_Cluster_eds_cluster_config(cluster); + if (eds_cluster_config != nullptr) { + fields.emplace_back("eds_cluster_config {"); + // eds_config + const struct envoy_api_v2_core_ConfigSource* eds_config = + envoy_api_v2_Cluster_EdsClusterConfig_eds_config(eds_cluster_config); + if (eds_config != nullptr) { + if (envoy_api_v2_core_ConfigSource_has_ads(eds_config)) { + fields.emplace_back(" eds_config { ads {} }"); + } else { + fields.emplace_back(" eds_config: "); + } + } + // service_name + AddStringField(" service_name", + envoy_api_v2_Cluster_EdsClusterConfig_service_name( + eds_cluster_config), + &fields); + fields.emplace_back("}"); + } + // lb_policy + fields.emplace_back( + absl::StrCat("lb_policy: ", envoy_api_v2_Cluster_lb_policy(cluster))); + // lrs_server + const envoy_api_v2_core_ConfigSource* lrs_server = + envoy_api_v2_Cluster_lrs_server(cluster); + if (lrs_server != nullptr) { + if (envoy_api_v2_core_ConfigSource_has_self(lrs_server)) { + fields.emplace_back("lrs_server { self {} }"); + } else { + fields.emplace_back("lrs_server: "); + } + } + gpr_log(GPR_DEBUG, "[xds_client %p] Cluster: %s", client, + absl::StrJoin(fields, "\n").c_str()); + } +} + +void MaybeLogClusterLoadAssignment( + XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_ClusterLoadAssignment* cla) { + if (GRPC_TRACE_FLAG_ENABLED(*tracer) && + gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { + // TODO(roth): When we can upgrade upb, use upb textformat code to dump + // the raw proto instead of doing this manually. + std::vector fields; + // cluster_name + AddStringField("cluster_name", + envoy_api_v2_ClusterLoadAssignment_cluster_name(cla), + &fields); + // endpoints + size_t num_localities; + const struct envoy_api_v2_endpoint_LocalityLbEndpoints* const* + locality_endpoints = + envoy_api_v2_ClusterLoadAssignment_endpoints(cla, &num_localities); + for (size_t i = 0; i < num_localities; ++i) { + const auto* locality_endpoint = locality_endpoints[i]; + fields.emplace_back("endpoints {"); + // locality + const auto* locality = + envoy_api_v2_endpoint_LocalityLbEndpoints_locality(locality_endpoint); + if (locality != nullptr) { + fields.emplace_back(" locality {"); + AddLocalityField(2, locality, &fields); + fields.emplace_back(" }"); + } + // lb_endpoints + size_t num_lb_endpoints; + const envoy_api_v2_endpoint_LbEndpoint* const* lb_endpoints = + envoy_api_v2_endpoint_LocalityLbEndpoints_lb_endpoints( + locality_endpoint, &num_lb_endpoints); + for (size_t j = 0; j < num_lb_endpoints; ++j) { + const auto* lb_endpoint = lb_endpoints[j]; + fields.emplace_back(" lb_endpoints {"); + // health_status + uint32_t health_status = + envoy_api_v2_endpoint_LbEndpoint_health_status(lb_endpoint); + if (health_status > 0) { + fields.emplace_back( + absl::StrCat(" health_status: ", health_status)); + } + // endpoint + const envoy_api_v2_endpoint_Endpoint* endpoint = + envoy_api_v2_endpoint_LbEndpoint_endpoint(lb_endpoint); + if (endpoint != nullptr) { + fields.emplace_back(" endpoint {"); + // address + const auto* address = + envoy_api_v2_endpoint_Endpoint_address(endpoint); + if (address != nullptr) { + fields.emplace_back(" address {"); + // socket_address + const auto* socket_address = + envoy_api_v2_core_Address_socket_address(address); + if (socket_address != nullptr) { + fields.emplace_back(" socket_address {"); + // address + AddStringField( + " address", + envoy_api_v2_core_SocketAddress_address(socket_address), + &fields); + // port_value + if (envoy_api_v2_core_SocketAddress_has_port_value( + socket_address)) { + fields.emplace_back( + absl::StrCat(" port_value: ", + envoy_api_v2_core_SocketAddress_port_value( + socket_address))); + } else { + fields.emplace_back(" "); + } + fields.emplace_back(" }"); + } else { + fields.emplace_back(" "); + } + fields.emplace_back(" }"); + } + fields.emplace_back(" }"); + } + fields.emplace_back(" }"); + } + // load_balancing_weight + const google_protobuf_UInt32Value* lb_weight = + envoy_api_v2_endpoint_LocalityLbEndpoints_load_balancing_weight( + locality_endpoint); + if (lb_weight != nullptr) { + fields.emplace_back( + absl::StrCat(" load_balancing_weight { value: ", + google_protobuf_UInt32Value_value(lb_weight), " }")); + } + // priority + uint32_t priority = + envoy_api_v2_endpoint_LocalityLbEndpoints_priority(locality_endpoint); + if (priority > 0) { + fields.emplace_back(absl::StrCat(" priority: ", priority)); + } + fields.emplace_back("}"); + } + // policy + const envoy_api_v2_ClusterLoadAssignment_Policy* policy = + envoy_api_v2_ClusterLoadAssignment_policy(cla); + if (policy != nullptr) { + fields.emplace_back("policy {"); + // drop_overloads + size_t num_drop_overloads; + const envoy_api_v2_ClusterLoadAssignment_Policy_DropOverload* const* + drop_overloads = + envoy_api_v2_ClusterLoadAssignment_Policy_drop_overloads( + policy, &num_drop_overloads); + for (size_t i = 0; i < num_drop_overloads; ++i) { + auto* drop_overload = drop_overloads[i]; + fields.emplace_back(" drop_overloads {"); + // category + AddStringField( + " category", + envoy_api_v2_ClusterLoadAssignment_Policy_DropOverload_category( + drop_overload), + &fields); + // drop_percentage + const auto* drop_percentage = + envoy_api_v2_ClusterLoadAssignment_Policy_DropOverload_drop_percentage( + drop_overload); + if (drop_percentage != nullptr) { + fields.emplace_back(" drop_percentage {"); + fields.emplace_back(absl::StrCat( + " numerator: ", + envoy_type_FractionalPercent_numerator(drop_percentage))); + fields.emplace_back(absl::StrCat( + " denominator: ", + envoy_type_FractionalPercent_denominator(drop_percentage))); + fields.emplace_back(" }"); + } + fields.emplace_back(" }"); + } + // overprovisioning_factor + fields.emplace_back("}"); + } + gpr_log(GPR_DEBUG, "[xds_client %p] ClusterLoadAssignment: %s", client, + absl::StrJoin(fields, "\n").c_str()); + } +} + // Better match type has smaller value. enum MatchType { EXACT_MATCH, @@ -449,8 +949,10 @@ MatchType DomainPatternMatchType(const std::string& domain_pattern) { } grpc_error* RouteConfigParse( + XdsClient* client, TraceFlag* tracer, const envoy_api_v2_RouteConfiguration* route_config, const std::string& expected_server_name, XdsApi::RdsUpdate* rds_update) { + MaybeLogRouteConfiguration(client, tracer, route_config); // Get the virtual hosts. size_t size; const envoy_api_v2_route_VirtualHost* const* virtual_hosts = @@ -540,7 +1042,8 @@ grpc_error* RouteConfigParse( return GRPC_ERROR_NONE; } -grpc_error* LdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, +grpc_error* LdsResponseParse(XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_DiscoveryResponse* response, const std::string& expected_server_name, XdsApi::LdsUpdate* lds_update, upb_arena* arena) { // Get the resources from the response. @@ -590,8 +1093,8 @@ grpc_error* LdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, envoy_config_filter_network_http_connection_manager_v2_HttpConnectionManager_route_config( http_connection_manager); XdsApi::RdsUpdate rds_update; - grpc_error* error = - RouteConfigParse(route_config, expected_server_name, &rds_update); + grpc_error* error = RouteConfigParse(client, tracer, route_config, + expected_server_name, &rds_update); if (error != GRPC_ERROR_NONE) return error; lds_update->rds_update.emplace(std::move(rds_update)); const upb_strview route_config_name = @@ -621,7 +1124,8 @@ grpc_error* LdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, "No listener found for expected server name."); } -grpc_error* RdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, +grpc_error* RdsResponseParse(XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_DiscoveryResponse* response, const std::string& expected_server_name, const std::string& expected_route_config_name, XdsApi::RdsUpdate* rds_update, upb_arena* arena) { @@ -655,8 +1159,8 @@ grpc_error* RdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, if (!upb_strview_eql(name, expected_name)) continue; // Parse the route_config. XdsApi::RdsUpdate local_rds_update; - grpc_error* error = - RouteConfigParse(route_config, expected_server_name, &local_rds_update); + grpc_error* error = RouteConfigParse( + client, tracer, route_config, expected_server_name, &local_rds_update); if (error != GRPC_ERROR_NONE) return error; *rds_update = std::move(local_rds_update); return GRPC_ERROR_NONE; @@ -665,7 +1169,8 @@ grpc_error* RdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, "No route config found for expected name."); } -grpc_error* CdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, +grpc_error* CdsResponseParse(XdsClient* client, TraceFlag* tracer, + const envoy_api_v2_DiscoveryResponse* response, XdsApi::CdsUpdateMap* cds_update_map, upb_arena* arena) { // Get the resources from the response. @@ -691,6 +1196,7 @@ grpc_error* CdsResponseParse(const envoy_api_v2_DiscoveryResponse* response, if (cluster == nullptr) { return GRPC_ERROR_CREATE_FROM_STATIC_STRING("Can't decode cluster."); } + MaybeLogCluster(client, tracer, cluster); // Check the cluster_discovery_type. if (!envoy_api_v2_Cluster_has_type(cluster)) { return GRPC_ERROR_CREATE_FROM_STATIC_STRING("DiscoveryType not found."); @@ -849,6 +1355,7 @@ grpc_error* DropParseAndAppend( } grpc_error* EdsResponsedParse( + XdsClient* client, TraceFlag* tracer, const envoy_api_v2_DiscoveryResponse* response, const std::set& expected_eds_service_names, XdsApi::EdsUpdateMap* eds_update_map, upb_arena* arena) { @@ -878,6 +1385,7 @@ grpc_error* EdsResponsedParse( return GRPC_ERROR_CREATE_FROM_STATIC_STRING( "Can't parse cluster_load_assignment."); } + MaybeLogClusterLoadAssignment(client, tracer, cluster_load_assignment); // Check the cluster name (which actually means eds_service_name). Ignore // unexpected names. upb_strview cluster_name = envoy_api_v2_ClusterLoadAssignment_cluster_name( @@ -950,6 +1458,7 @@ grpc_error* XdsApi::ParseAdsResponse( return GRPC_ERROR_CREATE_FROM_STATIC_STRING( "Can't decode the whole response."); } + MaybeLogDiscoveryResponse(client_, tracer_, response); // Record the type_url, the version_info, and the nonce of the response. upb_strview type_url_strview = envoy_api_v2_DiscoveryResponse_type_url(response); @@ -961,17 +1470,19 @@ grpc_error* XdsApi::ParseAdsResponse( *nonce = std::string(nonce_strview.data, nonce_strview.size); // Parse the response according to the resource type. if (*type_url == kLdsTypeUrl) { - return LdsResponseParse(response, expected_server_name, lds_update, - arena.ptr()); + return LdsResponseParse(client_, tracer_, response, expected_server_name, + lds_update, arena.ptr()); } else if (*type_url == kRdsTypeUrl) { - return RdsResponseParse(response, expected_server_name, + return RdsResponseParse(client_, tracer_, response, expected_server_name, expected_route_config_name, rds_update, arena.ptr()); } else if (*type_url == kCdsTypeUrl) { - return CdsResponseParse(response, cds_update_map, arena.ptr()); + return CdsResponseParse(client_, tracer_, response, cds_update_map, + arena.ptr()); } else if (*type_url == kEdsTypeUrl) { - return EdsResponsedParse(response, expected_eds_service_names, - eds_update_map, arena.ptr()); + return EdsResponsedParse(client_, tracer_, response, + expected_eds_service_names, eds_update_map, + arena.ptr()); } else { return GRPC_ERROR_CREATE_FROM_STATIC_STRING( "Unsupported ADS resource type."); @@ -980,6 +1491,121 @@ grpc_error* XdsApi::ParseAdsResponse( namespace { +void MaybeLogLrsRequest( + XdsClient* client, TraceFlag* tracer, + const envoy_service_load_stats_v2_LoadStatsRequest* request) { + if (GRPC_TRACE_FLAG_ENABLED(*tracer) && + gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { + // TODO(roth): When we can upgrade upb, use upb textformat code to dump + // the raw proto instead of doing this manually. + std::vector fields; + // node + const auto* node = + envoy_service_load_stats_v2_LoadStatsRequest_node(request); + if (node != nullptr) { + AddNodeLogFields(node, &fields); + } + // cluster_stats + size_t num_cluster_stats; + const struct envoy_api_v2_endpoint_ClusterStats* const* cluster_stats = + envoy_service_load_stats_v2_LoadStatsRequest_cluster_stats( + request, &num_cluster_stats); + for (size_t i = 0; i < num_cluster_stats; ++i) { + const auto* cluster_stat = cluster_stats[i]; + fields.emplace_back("cluster_stats {"); + // cluster_name + AddStringField( + " cluster_name", + envoy_api_v2_endpoint_ClusterStats_cluster_name(cluster_stat), + &fields); + // cluster_service_name + AddStringField( + " cluster_service_name", + envoy_api_v2_endpoint_ClusterStats_cluster_service_name(cluster_stat), + &fields); + // upstream_locality_stats + size_t num_stats; + const envoy_api_v2_endpoint_UpstreamLocalityStats* const* stats = + envoy_api_v2_endpoint_ClusterStats_upstream_locality_stats( + cluster_stat, &num_stats); + for (size_t j = 0; j < num_stats; ++j) { + const auto* stat = stats[j]; + fields.emplace_back(" upstream_locality_stats {"); + // locality + const auto* locality = + envoy_api_v2_endpoint_UpstreamLocalityStats_locality(stat); + if (locality != nullptr) { + fields.emplace_back(" locality {"); + AddLocalityField(3, locality, &fields); + fields.emplace_back(" }"); + } + // total_successful_requests + fields.emplace_back(absl::StrCat( + " total_successful_requests: ", + envoy_api_v2_endpoint_UpstreamLocalityStats_total_successful_requests( + stat))); + // total_requests_in_progress + fields.emplace_back(absl::StrCat( + " total_requests_in_progress: ", + envoy_api_v2_endpoint_UpstreamLocalityStats_total_requests_in_progress( + stat))); + // total_error_requests + fields.emplace_back(absl::StrCat( + " total_error_requests: ", + envoy_api_v2_endpoint_UpstreamLocalityStats_total_error_requests( + stat))); + // total_issued_requests + fields.emplace_back(absl::StrCat( + " total_issued_requests: ", + envoy_api_v2_endpoint_UpstreamLocalityStats_total_issued_requests( + stat))); + fields.emplace_back(" }"); + } + // total_dropped_requests + fields.emplace_back(absl::StrCat( + " total_dropped_requests: ", + envoy_api_v2_endpoint_ClusterStats_total_dropped_requests( + cluster_stat))); + // dropped_requests + size_t num_drops; + const envoy_api_v2_endpoint_ClusterStats_DroppedRequests* const* drops = + envoy_api_v2_endpoint_ClusterStats_dropped_requests(cluster_stat, + &num_drops); + for (size_t j = 0; j < num_drops; ++j) { + const auto* drop = drops[j]; + fields.emplace_back(" dropped_requests {"); + // category + AddStringField( + " category", + envoy_api_v2_endpoint_ClusterStats_DroppedRequests_category(drop), + &fields); + // dropped_count + fields.emplace_back(absl::StrCat( + " dropped_count: ", + envoy_api_v2_endpoint_ClusterStats_DroppedRequests_dropped_count( + drop))); + fields.emplace_back(" }"); + } + // load_report_interval + const auto* load_report_interval = + envoy_api_v2_endpoint_ClusterStats_load_report_interval(cluster_stat); + if (load_report_interval != nullptr) { + fields.emplace_back(" load_report_interval {"); + fields.emplace_back(absl::StrCat( + " seconds: ", + google_protobuf_Duration_seconds(load_report_interval))); + fields.emplace_back( + absl::StrCat(" nanos: ", + google_protobuf_Duration_nanos(load_report_interval))); + fields.emplace_back(" }"); + } + fields.emplace_back("}"); + } + gpr_log(GPR_DEBUG, "[xds_client %p] constructed LRS request: %s", client, + absl::StrJoin(fields, "\n").c_str()); + } +} + grpc_slice SerializeLrsRequest( const envoy_service_load_stats_v2_LoadStatsRequest* request, upb_arena* arena) { @@ -1002,6 +1628,7 @@ grpc_slice XdsApi::CreateLrsInitialRequest(const std::string& server_name) { arena.ptr()); PopulateNode(arena.ptr(), node_, build_version_, user_agent_name_, server_name, node_msg); + MaybeLogLrsRequest(client_, tracer_, request); return SerializeLrsRequest(request, arena.ptr()); } @@ -1114,6 +1741,7 @@ grpc_slice XdsApi::CreateLrsRequest( google_protobuf_Duration_set_seconds(load_report_interval, timespec.tv_sec); google_protobuf_Duration_set_nanos(load_report_interval, timespec.tv_nsec); } + MaybeLogLrsRequest(client_, tracer_, request); return SerializeLrsRequest(request, arena.ptr()); } diff --git a/src/core/ext/filters/client_channel/xds/xds_api.h b/src/core/ext/filters/client_channel/xds/xds_api.h index e894071b9af..9e2e0358e3c 100644 --- a/src/core/ext/filters/client_channel/xds/xds_api.h +++ b/src/core/ext/filters/client_channel/xds/xds_api.h @@ -34,6 +34,8 @@ namespace grpc_core { +class XdsClient; + class XdsApi { public: static const char* kLdsTypeUrl; @@ -187,7 +189,7 @@ class XdsApi { std::pair, ClusterLoadReport>; - explicit XdsApi(const XdsBootstrap::Node* node); + XdsApi(XdsClient* client, TraceFlag* tracer, const XdsBootstrap::Node* node); // Creates a request to nack an unsupported resource type. // Takes ownership of \a error. @@ -249,6 +251,8 @@ class XdsApi { grpc_millis* load_reporting_interval); private: + XdsClient* client_; + TraceFlag* tracer_; const XdsBootstrap::Node* node_; const std::string build_version_; const std::string user_agent_name_; diff --git a/src/core/ext/filters/client_channel/xds/xds_bootstrap.cc b/src/core/ext/filters/client_channel/xds/xds_bootstrap.cc index fcc079819bc..6a641714912 100644 --- a/src/core/ext/filters/client_channel/xds/xds_bootstrap.cc +++ b/src/core/ext/filters/client_channel/xds/xds_bootstrap.cc @@ -29,20 +29,97 @@ namespace grpc_core { -std::unique_ptr XdsBootstrap::ReadFromFile(grpc_error** error) { +namespace { + +UniquePtr BootstrapString(const XdsBootstrap& bootstrap) { + gpr_strvec v; + gpr_strvec_init(&v); + char* tmp; + if (bootstrap.node() != nullptr) { + gpr_asprintf(&tmp, + "node={\n" + " id=\"%s\",\n" + " cluster=\"%s\",\n" + " locality={\n" + " region=\"%s\",\n" + " zone=\"%s\",\n" + " subzone=\"%s\"\n" + " },\n" + " metadata=%s,\n" + "},\n", + bootstrap.node()->id.c_str(), + bootstrap.node()->cluster.c_str(), + bootstrap.node()->locality_region.c_str(), + bootstrap.node()->locality_zone.c_str(), + bootstrap.node()->locality_subzone.c_str(), + bootstrap.node()->metadata.Dump().c_str()); + gpr_strvec_add(&v, tmp); + } + gpr_asprintf(&tmp, + "servers=[\n" + " {\n" + " uri=\"%s\",\n" + " creds=[\n", + bootstrap.server().server_uri.c_str()); + gpr_strvec_add(&v, tmp); + for (size_t i = 0; i < bootstrap.server().channel_creds.size(); ++i) { + const auto& creds = bootstrap.server().channel_creds[i]; + gpr_asprintf(&tmp, " {type=\"%s\", config=%s},\n", creds.type.c_str(), + creds.config.Dump().c_str()); + gpr_strvec_add(&v, tmp); + } + gpr_strvec_add(&v, gpr_strdup(" ]\n }\n]")); + UniquePtr result(gpr_strvec_flatten(&v, nullptr)); + gpr_strvec_destroy(&v); + return result; +} + +} // namespace + +std::unique_ptr XdsBootstrap::ReadFromFile(XdsClient* client, + TraceFlag* tracer, + grpc_error** error) { grpc_core::UniquePtr path(gpr_getenv("GRPC_XDS_BOOTSTRAP")); if (path == nullptr) { *error = GRPC_ERROR_CREATE_FROM_STATIC_STRING( - "GRPC_XDS_BOOTSTRAP env var not set"); + "Environment variable GRPC_XDS_BOOTSTRAP not defined"); return nullptr; } + if (GRPC_TRACE_FLAG_ENABLED(*tracer)) { + gpr_log(GPR_INFO, + "[xds_client %p] Got bootstrap file location from " + "GRPC_XDS_BOOTSTRAP environment variable: %s", + client, path.get()); + } grpc_slice contents; *error = grpc_load_file(path.get(), /*add_null_terminator=*/true, &contents); if (*error != GRPC_ERROR_NONE) return nullptr; - Json json = Json::Parse(StringViewFromSlice(contents), error); + StringView contents_str_view = StringViewFromSlice(contents); + if (GRPC_TRACE_FLAG_ENABLED(*tracer)) { + UniquePtr str = StringViewToCString(contents_str_view); + gpr_log(GPR_DEBUG, "[xds_client %p] Bootstrap file contents: %s", client, + str.get()); + } + Json json = Json::Parse(contents_str_view, error); grpc_slice_unref_internal(contents); - if (*error != GRPC_ERROR_NONE) return nullptr; - return absl::make_unique(std::move(json), error); + if (*error != GRPC_ERROR_NONE) { + char* msg; + gpr_asprintf(&msg, "Failed to parse bootstrap file %s", path.get()); + grpc_error* error_out = + GRPC_ERROR_CREATE_REFERENCING_FROM_COPIED_STRING(msg, error, 1); + gpr_free(msg); + GRPC_ERROR_UNREF(*error); + *error = error_out; + return nullptr; + } + std::unique_ptr result = + absl::make_unique(std::move(json), error); + if (*error == GRPC_ERROR_NONE && GRPC_TRACE_FLAG_ENABLED(*tracer)) { + gpr_log(GPR_INFO, + "[xds_client %p] Bootstrap config for creating xds client:\n%s", + client, BootstrapString(*result).get()); + } + return result; } XdsBootstrap::XdsBootstrap(Json json, grpc_error** error) { diff --git a/src/core/ext/filters/client_channel/xds/xds_bootstrap.h b/src/core/ext/filters/client_channel/xds/xds_bootstrap.h index 26599aa9404..d3b04ad922f 100644 --- a/src/core/ext/filters/client_channel/xds/xds_bootstrap.h +++ b/src/core/ext/filters/client_channel/xds/xds_bootstrap.h @@ -33,6 +33,8 @@ namespace grpc_core { +class XdsClient; + class XdsBootstrap { public: struct Node { @@ -56,7 +58,9 @@ class XdsBootstrap { // If *error is not GRPC_ERROR_NONE after returning, then there was an // error reading the file. - static std::unique_ptr ReadFromFile(grpc_error** error); + static std::unique_ptr ReadFromFile(XdsClient* client, + TraceFlag* tracer, + grpc_error** error); // Do not instantiate directly -- use ReadFromFile() above instead. XdsBootstrap(Json json, grpc_error** error); diff --git a/src/core/ext/filters/client_channel/xds/xds_client.cc b/src/core/ext/filters/client_channel/xds/xds_client.cc index 42708fca556..58a80849236 100644 --- a/src/core/ext/filters/client_channel/xds/xds_client.cc +++ b/src/core/ext/filters/client_channel/xds/xds_client.cc @@ -22,6 +22,8 @@ #include #include +#include "absl/strings/str_join.h" + #include #include #include @@ -788,33 +790,46 @@ void XdsClient::ChannelState::AdsCallState::SendMessageLocked( return; } auto& state = state_map_[type_url]; - grpc_error* error = state.error; - state.error = GRPC_ERROR_NONE; grpc_slice request_payload_slice; + std::set resource_names; if (type_url == XdsApi::kLdsTypeUrl) { + resource_names.insert(xds_client()->server_name_); request_payload_slice = xds_client()->api_.CreateLdsRequest( - xds_client()->server_name_, state.version, state.nonce, error, - !sent_initial_message_); + xds_client()->server_name_, state.version, state.nonce, + GRPC_ERROR_REF(state.error), !sent_initial_message_); state.subscribed_resources[xds_client()->server_name_]->Start(Ref()); } else if (type_url == XdsApi::kRdsTypeUrl) { + resource_names.insert(xds_client()->route_config_name_); request_payload_slice = xds_client()->api_.CreateRdsRequest( - xds_client()->route_config_name_, state.version, state.nonce, error, - !sent_initial_message_); + xds_client()->route_config_name_, state.version, state.nonce, + GRPC_ERROR_REF(state.error), !sent_initial_message_); state.subscribed_resources[xds_client()->route_config_name_]->Start(Ref()); } else if (type_url == XdsApi::kCdsTypeUrl) { + resource_names = ClusterNamesForRequest(); request_payload_slice = xds_client()->api_.CreateCdsRequest( - ClusterNamesForRequest(), state.version, state.nonce, error, + resource_names, state.version, state.nonce, GRPC_ERROR_REF(state.error), !sent_initial_message_); } else if (type_url == XdsApi::kEdsTypeUrl) { + resource_names = EdsServiceNamesForRequest(); request_payload_slice = xds_client()->api_.CreateEdsRequest( - EdsServiceNamesForRequest(), state.version, state.nonce, error, + resource_names, state.version, state.nonce, GRPC_ERROR_REF(state.error), !sent_initial_message_); } else { request_payload_slice = xds_client()->api_.CreateUnsupportedTypeNackRequest( - type_url, state.nonce, state.error); + type_url, state.nonce, GRPC_ERROR_REF(state.error)); state_map_.erase(type_url); } sent_initial_message_ = true; + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_client_trace)) { + gpr_log(GPR_INFO, + "[xds_client %p] sending ADS request: type=%s version=%s nonce=%s " + "error=%s resources=%s", + xds_client(), type_url.c_str(), state.version.c_str(), + state.nonce.c_str(), grpc_error_string(state.error), + absl::StrJoin(resource_names, " ").c_str()); + } + GRPC_ERROR_UNREF(state.error); + state.error = GRPC_ERROR_NONE; // Create message payload. send_message_payload_ = grpc_raw_byte_buffer_create(&request_payload_slice, 1); @@ -1150,7 +1165,8 @@ void XdsClient::ChannelState::AdsCallState::OnResponseReceivedLocked( grpc_slice_unref_internal(response_slice); if (type_url.empty()) { // Ignore unparsable response. - gpr_log(GPR_ERROR, "[xds_client %p] No type_url found. error=%s", + gpr_log(GPR_ERROR, + "[xds_client %p] Error parsing ADS response (%s) -- ignoring", xds_client, grpc_error_string(parse_error)); GRPC_ERROR_UNREF(parse_error); } else { @@ -1162,10 +1178,11 @@ void XdsClient::ChannelState::AdsCallState::OnResponseReceivedLocked( GRPC_ERROR_UNREF(state.error); state.error = parse_error; // NACK unacceptable update. - gpr_log( - GPR_ERROR, - "[xds_client %p] ADS response can't be accepted, NACKing. error=%s", - xds_client, grpc_error_string(parse_error)); + gpr_log(GPR_ERROR, + "[xds_client %p] ADS response invalid for resource type %s " + "version %s, will NACK: nonce=%s error=%s", + xds_client, type_url.c_str(), version.c_str(), + state.nonce.c_str(), grpc_error_string(parse_error)); ads_calld->SendMessageLocked(type_url); } else { ads_calld->seen_response_ = true; @@ -1727,10 +1744,15 @@ XdsClient::XdsClient(Combiner* combiner, grpc_pollset_set* interested_parties, request_timeout_(GetRequestTimeout(channel_args)), combiner_(GRPC_COMBINER_REF(combiner, "xds_client")), interested_parties_(interested_parties), - bootstrap_(XdsBootstrap::ReadFromFile(error)), - api_(bootstrap_ == nullptr ? nullptr : bootstrap_->node()), + bootstrap_( + XdsBootstrap::ReadFromFile(this, &grpc_xds_client_trace, error)), + api_(this, &grpc_xds_client_trace, + bootstrap_ == nullptr ? nullptr : bootstrap_->node()), server_name_(server_name), service_config_watcher_(std::move(watcher)) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_client_trace)) { + gpr_log(GPR_INFO, "[xds_client %p] creating xds client", this); + } if (*error != GRPC_ERROR_NONE) { gpr_log(GPR_ERROR, "[xds_client %p] failed to read bootstrap file: %s", this, grpc_error_string(*error)); @@ -1755,9 +1777,17 @@ XdsClient::XdsClient(Combiner* combiner, grpc_pollset_set* interested_parties, } } -XdsClient::~XdsClient() { GRPC_COMBINER_UNREF(combiner_, "xds_client"); } +XdsClient::~XdsClient() { + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_client_trace)) { + gpr_log(GPR_INFO, "[xds_client %p] destroying xds client", this); + } + GRPC_COMBINER_UNREF(combiner_, "xds_client"); +} void XdsClient::Orphan() { + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_client_trace)) { + gpr_log(GPR_INFO, "[xds_client %p] shutting down xds client", this); + } shutting_down_ = true; chand_.reset(); // We do not clear cluster_map_ and endpoint_map_ if the xds client was @@ -1782,6 +1812,10 @@ void XdsClient::WatchClusterData( // If we've already received an CDS update, notify the new watcher // immediately. if (cluster_state.update.has_value()) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_client_trace)) { + gpr_log(GPR_INFO, "[xds_client %p] returning cached cluster data for %s", + this, StringViewToCString(cluster_name).get()); + } w->OnClusterChanged(cluster_state.update.value()); } chand_->Subscribe(XdsApi::kCdsTypeUrl, cluster_name_str); @@ -1812,6 +1846,10 @@ void XdsClient::WatchEndpointData( // If we've already received an EDS update, notify the new watcher // immediately. if (!endpoint_state.update.priority_list_update.empty()) { + if (GRPC_TRACE_FLAG_ENABLED(grpc_xds_client_trace)) { + gpr_log(GPR_INFO, "[xds_client %p] returning cached endpoint data for %s", + this, StringViewToCString(eds_service_name).get()); + } w->OnEndpointChanged(endpoint_state.update); } chand_->Subscribe(XdsApi::kEdsTypeUrl, eds_service_name_str);