From fe9e0ec88134085b955e4d62b6a2854cd3f58c8f Mon Sep 17 00:00:00 2001 From: Daniel Azuma Date: Thu, 5 Dec 2024 13:11:43 -0800 Subject: [PATCH] feat(common): Log requests and responses (#1112) --- gapic-common/.rubocop.yml | 6 + gapic-common/Gemfile | 1 + gapic-common/gapic-common.gemspec | 6 +- gapic-common/lib/gapic/grpc/service_stub.rb | 18 +- .../lib/gapic/grpc/service_stub/channel.rb | 6 +- .../gapic/grpc/service_stub/channel_pool.rb | 11 +- .../lib/gapic/grpc/service_stub/rpc_call.rb | 118 ++++++++- gapic-common/lib/gapic/logging_concerns.rb | 210 ++++++++++++++++ gapic-common/lib/gapic/rest/client_stub.rb | 109 +++++++-- .../test/gapic/grpc/channel/channel_test.rb | 2 +- .../grpc/channel_pool/channel_pool_test.rb | 2 +- gapic-common/test/gapic/grpc/logging_test.rb | 229 ++++++++++++++++++ .../test/gapic/grpc/rpc_call/raise_test.rb | 12 +- .../test/gapic/grpc/service_stub_test.rb | 158 +++++------- gapic-common/test/gapic/grpc/stub_test.rb | 55 ++--- .../test/gapic/logging_concerns_test.rb | 32 +++ .../rest/client_stub/retry/raise_test.rb | 1 + .../rest/client_stub/retry/retry_test.rb | 10 +- gapic-common/test/gapic/rest/logging_test.rb | 143 +++++++++++ gapic-common/test/test_helper.rb | 17 ++ 20 files changed, 962 insertions(+), 184 deletions(-) create mode 100644 gapic-common/lib/gapic/logging_concerns.rb create mode 100644 gapic-common/test/gapic/grpc/logging_test.rb create mode 100644 gapic-common/test/gapic/logging_concerns_test.rb create mode 100644 gapic-common/test/gapic/rest/logging_test.rb diff --git a/gapic-common/.rubocop.yml b/gapic-common/.rubocop.yml index d2f82c186..7c8b830c0 100644 --- a/gapic-common/.rubocop.yml +++ b/gapic-common/.rubocop.yml @@ -11,9 +11,15 @@ Metrics/ClassLength: Metrics/CyclomaticComplexity: Max: 15 +Metrics/MethodLength: + Max: 30 + Metrics/PerceivedComplexity: Max: 15 +Naming/AccessorMethodName: + Enabled: false + Naming/FileName: Exclude: - "lib/gapic-common.rb" diff --git a/gapic-common/Gemfile b/gapic-common/Gemfile index 48e0ba127..06af15b56 100644 --- a/gapic-common/Gemfile +++ b/gapic-common/Gemfile @@ -3,6 +3,7 @@ source "https://rubygems.org" gemspec gem "concurrent-ruby", "~> 1.3" +gem "googleapis-common-protos-types", "~> 1.15" gem "google-cloud-core", "~> 1.7" gem "google-style", "~> 1.30.0" gem "grpc-tools", "~> 1.65" diff --git a/gapic-common/gapic-common.gemspec b/gapic-common/gapic-common.gemspec index c6d16430c..768a6acc5 100644 --- a/gapic-common/gapic-common.gemspec +++ b/gapic-common/gapic-common.gemspec @@ -39,7 +39,9 @@ Gem::Specification.new do |spec| spec.add_dependency "faraday-retry", ">= 1.0", "< 3.a" spec.add_dependency "googleapis-common-protos", "~> 1.6" spec.add_dependency "googleapis-common-protos-types", "~> 1.15" - spec.add_dependency "googleauth", "~> 1.11" + spec.add_dependency "googleauth", "~> 1.12" + spec.add_dependency "google-cloud-env", "~> 2.2" + spec.add_dependency "google-logging-utils", "~> 0.1" spec.add_dependency "google-protobuf", ">= 3.25", "< 5.a" - spec.add_dependency "grpc", "~> 1.65" + spec.add_dependency "grpc", "~> 1.66" end diff --git a/gapic-common/lib/gapic/grpc/service_stub.rb b/gapic-common/lib/gapic/grpc/service_stub.rb index eb5c33ac1..05646ad7d 100644 --- a/gapic-common/lib/gapic/grpc/service_stub.rb +++ b/gapic-common/lib/gapic/grpc/service_stub.rb @@ -17,6 +17,7 @@ require "gapic/grpc/service_stub/rpc_call" require "gapic/grpc/service_stub/channel" require "gapic/grpc/service_stub/channel_pool" +require "gapic/logging_concerns" require "gapic/universe_domain_concerns" module Gapic @@ -32,6 +33,7 @@ module Gapic # class ServiceStub include UniverseDomainConcerns + include LoggingConcerns attr_reader :grpc_stub attr_reader :channel_pool @@ -64,6 +66,9 @@ class ServiceStub # be used for intercepting calls before they are executed Interceptors are an EXPERIMENTAL API. # @param channel_pool_config [::Gapic::ServiceStub:ChannelPool::Configuration] The configuration for channel # pool. This argument will raise error when `credentials` is provided as a `::GRPC::Core::Channel`. + # @param logger [Logger,:default,nil] An explicit logger to use, or one + # of the values `:default` (the default) to construct a default logger, + # or `nil` to disable logging explicitly. # def initialize grpc_stub_class, credentials:, @@ -72,13 +77,19 @@ def initialize grpc_stub_class, universe_domain: nil, channel_args: nil, interceptors: nil, - channel_pool_config: nil + channel_pool_config: nil, + logger: :default raise ArgumentError, "grpc_stub_class is required" if grpc_stub_class.nil? setup_universe_domain universe_domain: universe_domain, endpoint: endpoint, endpoint_template: endpoint_template, credentials: credentials + setup_logging logger: logger, + system_name: grpc_stub_class, + service: grpc_stub_class, + endpoint: self.endpoint, + client_id: object_id @channel_pool = nil @grpc_stub = nil @@ -102,7 +113,7 @@ def create_channel_pool grpc_stub_class, endpoint:, credentials:, channel_args: end @channel_pool = ChannelPool.new grpc_stub_class, endpoint: endpoint, credentials: credentials, channel_args: channel_args, interceptors: interceptors, - config: channel_pool_config + config: channel_pool_config, stub_logger: stub_logger end def create_grpc_stub grpc_stub_class, endpoint:, credentials:, channel_args: nil, interceptors: nil @@ -201,7 +212,8 @@ def create_grpc_stub grpc_stub_class, endpoint:, credentials:, channel_args: nil # def call_rpc method_name, request, options: nil, &block if @channel_pool.nil? - rpc_call = RpcCall.new @grpc_stub.method method_name + meth = @grpc_stub.method method_name + rpc_call = RpcCall.new meth, stub_logger: stub_logger, method_name: method_name rpc_call.call request, options: options, &block else @channel_pool.call_rpc method_name, request, options: options, &block diff --git a/gapic-common/lib/gapic/grpc/service_stub/channel.rb b/gapic-common/lib/gapic/grpc/service_stub/channel.rb index 39aebab1e..220de54db 100644 --- a/gapic-common/lib/gapic/grpc/service_stub/channel.rb +++ b/gapic-common/lib/gapic/grpc/service_stub/channel.rb @@ -32,12 +32,13 @@ class Channel # Creates a new Channel instance # def initialize grpc_stub_class, endpoint:, credentials:, channel_args: nil, interceptors: nil, - on_channel_create: nil + on_channel_create: nil, stub_logger: nil @grpc_stub_class = grpc_stub_class @endpoint = endpoint @credentials = credentials @channel_args = Hash channel_args @interceptors = Array interceptors + @stub_logger = stub_logger @concurrent_streams = 0 @mutex = Mutex.new setup_grpc_stub @@ -88,7 +89,8 @@ def setup_grpc_stub def call_rpc method_name, request, options: nil, &block @mutex.synchronize { @concurrent_streams += 1 } begin - rpc_call = RpcCall.new @grpc_stub.method method_name + meth = @grpc_stub.method method_name + rpc_call = RpcCall.new meth, stub_logger: @stub_logger, method_name: method_name response = rpc_call.call request, options: options, &block response ensure diff --git a/gapic-common/lib/gapic/grpc/service_stub/channel_pool.rb b/gapic-common/lib/gapic/grpc/service_stub/channel_pool.rb index e66b8ef25..efb5a857d 100644 --- a/gapic-common/lib/gapic/grpc/service_stub/channel_pool.rb +++ b/gapic-common/lib/gapic/grpc/service_stub/channel_pool.rb @@ -30,7 +30,12 @@ class ChannelPool ## # Initialize an instance of ServiceStub::ChannelPool # - def initialize grpc_stub_class, endpoint:, credentials:, channel_args: nil, interceptors: nil, config: nil + def initialize grpc_stub_class, + endpoint:, credentials:, + channel_args: nil, + interceptors: nil, + config: nil, + stub_logger: nil if credentials.is_a? ::GRPC::Core::Channel raise ArgumentError, "Can't create a channel pool with GRPC::Core::Channel as credentials" end @@ -41,6 +46,7 @@ def initialize grpc_stub_class, endpoint:, credentials:, channel_args: nil, inte @channel_args = channel_args @interceptors = interceptors @config = config || Configuration.new + @stub_logger = stub_logger @channels = (1..@config.channel_count).map { create_channel } end @@ -49,7 +55,8 @@ def initialize grpc_stub_class, endpoint:, credentials:, channel_args: nil, inte # Creates a new channel. def create_channel Channel.new @grpc_stub_class, endpoint: @endpoint, credentials: @credentials, channel_args: @channel_args, - interceptors: @interceptors, on_channel_create: @config.on_channel_create + interceptors: @interceptors, on_channel_create: @config.on_channel_create, + stub_logger: @stub_logger end ## diff --git a/gapic-common/lib/gapic/grpc/service_stub/rpc_call.rb b/gapic-common/lib/gapic/grpc/service_stub/rpc_call.rb index d37fc31f6..9fe8430a4 100644 --- a/gapic-common/lib/gapic/grpc/service_stub/rpc_call.rb +++ b/gapic-common/lib/gapic/grpc/service_stub/rpc_call.rb @@ -13,6 +13,7 @@ # limitations under the License. require "gapic/call_options" +require "gapic/logging_concerns" require "grpc/errors" module Gapic @@ -32,8 +33,11 @@ class RpcCall # # @param stub_method [Proc] Used to make a bare rpc call. # - def initialize stub_method + def initialize stub_method, stub_logger: nil, method_name: nil @stub_method = stub_method + @stub_logger = stub_logger + @method_name = method_name + @request_id = LoggingConcerns.random_uuid4 end ## @@ -44,7 +48,8 @@ def initialize stub_method # customize the options object, using keys that match the arguments for {Gapic::CallOptions.new}. This object # should only be used once. # - # @yield [response, operation] Access the response along with the RPC operation. + # @yield [response, operation] Access the response along with the RPC operation. Additionally, throwing + # `:response, obj` within the block will change the return value to `obj`. # @yieldparam response [Object] The response object. # @yieldparam operation [::GRPC::ActiveCall::Operation] The RPC operation for the response. # @@ -91,7 +96,7 @@ def initialize stub_method # ) # response = echo_call.call request, options: options # - # @example Accessing the response and RPC operation using a block: + # @example Accessing the RPC operation using a block: # require "google/showcase/v1beta1/echo_pb" # require "google/showcase/v1beta1/echo_services_pb" # require "gapic" @@ -107,8 +112,8 @@ def initialize stub_method # echo_call = Gapic::ServiceStub::RpcCall.new echo_stub.method :echo # # request = Google::Showcase::V1beta1::EchoRequest.new - # echo_call.call request do |response, operation| - # operation.trailing_metadata + # metadata = echo_call.call request do |_response, operation| + # throw :response, operation.trailing_metadata # end # def call request, options: nil @@ -117,21 +122,27 @@ def call request, options: nil deadline = calculate_deadline options metadata = options.metadata + try_number = 1 retried_exception = nil begin + request = log_request request, metadata, try_number operation = stub_method.call request, deadline: deadline, metadata: metadata, return_op: true response = operation.execute - yield response, operation if block_given? - response + catch :response do + response = log_response response, try_number + yield response, operation if block_given? + response + end rescue ::GRPC::DeadlineExceeded => e + log_response e, try_number raise Gapic::GRPC::DeadlineExceededError.new e.message, root_cause: retried_exception rescue StandardError => e - if e.is_a?(::GRPC::Unavailable) && /Signet::AuthorizationError/ =~ e.message - e = Gapic::GRPC::AuthorizationError.new e.message.gsub(%r{^\d+:}, "") - end + e = normalize_exception e + log_response e, try_number if check_retry?(deadline) && options.retry_policy.call(e) retried_exception = e + try_number += 1 retry end @@ -163,6 +174,93 @@ def current_time nsecs_part = nanos % 1_000_000_000 Time.at secs_part, nsecs_part, :nanosecond end + + def normalize_exception exception + if exception.is_a?(::GRPC::Unavailable) && /Signet::AuthorizationError/ =~ exception.message + exception = Gapic::GRPC::AuthorizationError.new exception.message.gsub(%r{^\d+:}, "") + end + exception + end + + def log_request request, metadata, try_number + return request unless @stub_logger + @stub_logger.info do |entry| + entry.set_system_name + entry.set_service + entry.set "rpcName", @method_name + entry.set "retryAttempt", try_number + entry.set "requestId", @request_id + entry.message = + if request.is_a? Enumerable + "Sending stream to #{entry.service}.#{@method_name} (try #{try_number})" + else + "Sending request to #{entry.service}.#{@method_name} (try #{try_number})" + end + end + loggable_metadata = metadata.to_h rescue {} + if request.is_a? Enumerable + request.lazy.map do |req| + log_single_request req, loggable_metadata + end + else + log_single_request request, loggable_metadata + end + end + + def log_single_request request, metadata + request_content = request.respond_to?(:to_h) ? (request.to_h rescue {}) : request.to_s + if !request_content.empty? || !metadata.empty? + @stub_logger.debug do |entry| + entry.set "requestId", @request_id + entry.set "request", request_content + entry.set "headers", metadata + entry.message = "(request payload as #{request.class})" + end + end + request + end + + def log_response response, try_number + return response unless @stub_logger + @stub_logger.info do |entry| + entry.set_system_name + entry.set_service + entry.set "rpcName", @method_name + entry.set "retryAttempt", try_number + entry.set "requestId", @request_id + case response + when StandardError + entry.set "exception", response.to_s + entry.message = "Received error for #{entry.service}.#{@method_name} (try #{try_number}): #{response}" + when Enumerable + entry.message = "Receiving stream for #{entry.service}.#{@method_name} (try #{try_number})" + else + entry.message = "Received response for #{entry.service}.#{@method_name} (try #{try_number})" + end + end + case response + when StandardError + response + when Enumerable + response.lazy.map do |resp| + log_single_response resp + end + else + log_single_response response + end + end + + def log_single_response response + response_content = response.respond_to?(:to_h) ? (response.to_h rescue {}) : response.to_s + unless response_content.empty? + @stub_logger.debug do |entry| + entry.set "requestId", @request_id + entry.set "response", response_content + entry.message = "(response payload as #{response.class})" + end + end + response + end end end end diff --git a/gapic-common/lib/gapic/logging_concerns.rb b/gapic-common/lib/gapic/logging_concerns.rb new file mode 100644 index 000000000..24aa9eae5 --- /dev/null +++ b/gapic-common/lib/gapic/logging_concerns.rb @@ -0,0 +1,210 @@ +# Copyright 2024 Google LLC +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# https://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +require "google/cloud/env" +require "google/logging/message" +require "google/logging/structured_formatter" + +module Gapic + ## + # A mixin module that handles logging setup for a stub. + # + module LoggingConcerns + ## + # The logger for this object. + # + # @return [Logger] + # + attr_reader :logger + + ## + # @private + # A convenience object used by stub-based logging. + # + class StubLogger + OMIT_FILES = [ + /^#{Regexp.escape __dir__}/ + ].freeze + + def initialize logger: nil, **kwargs + @logger = logger + @kwargs = kwargs + end + + def log severity + return unless @logger + locations = caller_locations + @logger.add severity do + builder = LogEntryBuilder.new(**@kwargs) + builder.set_source_location_from locations + yield builder + builder.build + rescue StandardError + # Do nothing + end + end + + def info &block + log Logger::INFO, &block + end + + def debug &block + log Logger::DEBUG, &block + end + + ## + # @private + # Builder for a log entry, passed to {StubLogger#log}. + # + class LogEntryBuilder + def initialize system_name: nil, + service: nil, + endpoint: nil, + client_id: nil + @system_name = system_name + @service = service + @endpoint = endpoint + @client_id = client_id + @message = nil + @caller_locations = caller_locations + @fields = { "clientId" => @client_id } + end + + attr_reader :system_name + + attr_reader :service + + attr_reader :endpoint + + attr_accessor :message + + attr_writer :source_location + + attr_reader :fields + + def set name, value + fields[name] = value + end + + def set_system_name + set "system", system_name + end + + def set_service + set "serviceName", service + end + + def set_credentials_fields creds + creds = creds.client if creds.respond_to? :client + set "credentialsId", creds.object_id + set "credentialsType", creds.class.name + set "credentialsScope", creds.scope if creds.respond_to? :scope + set "useSelfSignedJWT", creds.enable_self_signed_jwt? if creds.respond_to? :enable_self_signed_jwt? + set "universeDomain", creds.universe_domain if creds.respond_to? :universe_domain + end + + def source_location + @source_location ||= Google::Logging::SourceLocation.for_caller omit_files: OMIT_FILES, + locations: @caller_locations + end + + def set_source_location_from locations + @caller_locations = locations + @source_location = nil + end + + def build + Google::Logging::Message.from message: message, source_location: source_location, fields: fields + end + end + end + + ## + # @private + # Initialize logging concerns. + # + def setup_logging logger: :default, + stream: nil, + formatter: nil, + level: nil, + system_name: nil, + service: nil, + endpoint: nil, + client_id: nil + service = LoggingConcerns.normalize_service service + system_name = LoggingConcerns.normalize_system_name system_name + logging_env = ENV["GOOGLE_SDK_RUBY_LOGGING_GEMS"].to_s.downcase + logger = nil if ["false", "none"].include? logging_env + if logger == :default + logger = nil + if ["true", "all"].include?(logging_env) || logging_env.split(",").include?(system_name) + stream ||= $stderr + level ||= "DEBUG" + formatter ||= Google::Logging::StructuredFormatter.new if Google::Cloud::Env.get.logging_agent_expected? + logger = Logger.new stream, progname: system_name, level: level, formatter: formatter + end + end + @logger = logger + @stub_logger = StubLogger.new logger: logger, + system_name: system_name, + service: service, + endpoint: endpoint, + client_id: client_id + end + + # @private + attr_reader :stub_logger + + class << self + # @private + def random_uuid4 + ary = Random.bytes 16 + ary.setbyte 6, ((ary.getbyte(6) & 0x0f) | 0x40) + ary.setbyte 8, ((ary.getbyte(8) & 0x3f) | 0x80) + ary.unpack("H8H4H4H4H12").join "-" + end + + # @private + def normalize_system_name input + case input + when String + input + when Class + input.name.split("::")[..-3] + .map { |elem| elem.scan(/[A-Z][A-Z]*(?=[A-Z][a-z0-9]|$)|[A-Z][a-z0-9]+/).map(&:downcase).join("_") } + .join("-") + else + "googleapis" + end + end + + # @private + def normalize_service input + case input + when String + input + when Class + mod = input.name.split("::")[..-2].inject(Object) { |m, n| m.const_get n } + if mod.const_defined? "Service" + mod.const_get("Service").service_name + else + name_segments = input.name.split("::")[..-3] + mod = name_segments.inject(Object) { |m, n| m.const_get n } + name_segments.join "." if mod.const_defined? "Rest" + end + end + end + end + end +end diff --git a/gapic-common/lib/gapic/rest/client_stub.rb b/gapic-common/lib/gapic/rest/client_stub.rb index c2bb368c7..e886db5e4 100644 --- a/gapic-common/lib/gapic/rest/client_stub.rb +++ b/gapic-common/lib/gapic/rest/client_stub.rb @@ -13,6 +13,7 @@ # limitations under the License. require "googleauth" +require "gapic/logging_concerns" require "gapic/rest/faraday_middleware" require "gapic/universe_domain_concerns" require "faraday/retry" @@ -28,9 +29,11 @@ module Rest # class ClientStub include UniverseDomainConcerns + include LoggingConcerns ## # Initializes with an endpoint and credentials + # # @param endpoint [String] The endpoint of the API. Overrides any endpoint_template. # @param endpoint_template [String] The endpoint of the API, where the # universe domain component of the hostname is marked by the string in @@ -41,12 +44,14 @@ class ClientStub # Credentials to send with calls in form of a googleauth credentials object. # (see the [googleauth docs](https://googleapis.dev/ruby/googleauth/latest/index.html)) # @param numeric_enums [Boolean] Whether to signal the server to JSON-encode enums as ints - # # @param raise_faraday_errors [Boolean] # Whether to raise Faraday errors instead of wrapping them in `Gapic::Rest::Error` # Added for backwards compatibility. # Default is `true`. All REST clients (except for old versions of `google-cloud-compute-v1`) # should explicitly set this parameter to `false`. + # @param logger [Logger,:default,nil] An explicit logger to use, or one + # of the values `:default` (the default) to construct a default logger, + # or `nil` to disable logging explicitly. # # @yield [Faraday::Connection] # @@ -55,7 +60,10 @@ def initialize credentials:, endpoint_template: nil, universe_domain: nil, numeric_enums: false, - raise_faraday_errors: true + raise_faraday_errors: true, + logging_system: nil, + service_name: nil, + logger: :default setup_universe_domain universe_domain: universe_domain, endpoint: endpoint, endpoint_template: endpoint_template, @@ -65,6 +73,12 @@ def initialize credentials:, endpoint_url = "https://#{endpoint_url}" unless /^https?:/.match? endpoint_url endpoint_url = endpoint_url.sub %r{/$}, "" + setup_logging logger: logger, + system_name: logging_system, + service: service_name, + endpoint: endpoint_url, + client_id: object_id + @numeric_enums = numeric_enums @raise_faraday_errors = raise_faraday_errors @@ -88,8 +102,8 @@ def initialize credentials:, # @param options [::Gapic::CallOptions,Hash] gapic options to be applied # to the REST call. Currently only timeout and headers are supported. # @return [Faraday::Response] - def make_get_request uri:, params: {}, options: {} - make_http_request :get, uri: uri, body: nil, params: params, options: options + def make_get_request uri:, params: {}, options: {}, method_name: nil + make_http_request :get, uri: uri, body: nil, params: params, options: options, method_name: method_name end ## @@ -100,8 +114,8 @@ def make_get_request uri:, params: {}, options: {} # @param options [::Gapic::CallOptions,Hash] gapic options to be applied # to the REST call. Currently only timeout and headers are supported. # @return [Faraday::Response] - def make_delete_request uri:, params: {}, options: {} - make_http_request :delete, uri: uri, body: nil, params: params, options: options + def make_delete_request uri:, params: {}, options: {}, method_name: nil + make_http_request :delete, uri: uri, body: nil, params: params, options: options, method_name: method_name end ## @@ -113,8 +127,8 @@ def make_delete_request uri:, params: {}, options: {} # @param options [::Gapic::CallOptions,Hash] gapic options to be applied # to the REST call. Currently only timeout and headers are supported. # @return [Faraday::Response] - def make_patch_request uri:, body:, params: {}, options: {} - make_http_request :patch, uri: uri, body: body, params: params, options: options + def make_patch_request uri:, body:, params: {}, options: {}, method_name: nil + make_http_request :patch, uri: uri, body: body, params: params, options: options, method_name: method_name end ## @@ -126,8 +140,8 @@ def make_patch_request uri:, body:, params: {}, options: {} # @param options [::Gapic::CallOptions,Hash] gapic options to be applied # to the REST call. Currently only timeout and headers are supported. # @return [Faraday::Response] - def make_post_request uri:, body: nil, params: {}, options: {} - make_http_request :post, uri: uri, body: body, params: params, options: options + def make_post_request uri:, body: nil, params: {}, options: {}, method_name: nil + make_http_request :post, uri: uri, body: body, params: params, options: options, method_name: method_name end ## @@ -139,8 +153,8 @@ def make_post_request uri:, body: nil, params: {}, options: {} # @param options [::Gapic::CallOptions,Hash] gapic options to be applied # to the REST call. Currently only timeout and headers are supported. # @return [Faraday::Response] - def make_put_request uri:, body: nil, params: {}, options: {} - make_http_request :put, uri: uri, body: body, params: params, options: options + def make_put_request uri:, body: nil, params: {}, options: {}, method_name: nil + make_http_request :put, uri: uri, body: body, params: params, options: options, method_name: method_name end ## @@ -154,27 +168,38 @@ def make_put_request uri:, body: nil, params: {}, options: {} # @param is_server_streaming [Boolean] flag if method is streaming # @yieldparam chunk [String] The chunk of data received during server streaming. # @return [Faraday::Response] - def make_http_request verb, uri:, body:, params:, options:, is_server_streaming: false, &block + def make_http_request verb, + uri:, body:, params:, options:, + is_server_streaming: false, method_name: nil, + &block # Converts hash and nil to an options object options = ::Gapic::CallOptions.new(**options.to_h) unless options.is_a? ::Gapic::CallOptions deadline = calculate_deadline options retried_exception = nil next_timeout = get_timeout deadline + request_id = LoggingConcerns.random_uuid4 + try_number = 1 begin - base_make_http_request(verb: verb, uri: uri, body: body, - params: params, metadata: options.metadata, - timeout: next_timeout, - is_server_streaming: is_server_streaming, - &block) + log_request method_name, request_id, try_number, body, options.metadata + response = base_make_http_request verb: verb, uri: uri, body: body, + params: params, metadata: options.metadata, + timeout: next_timeout, + is_server_streaming: is_server_streaming, + &block + log_response method_name, request_id, try_number, response, is_server_streaming + response rescue ::Faraday::TimeoutError => e + log_response method_name, request_id, try_number, e, is_server_streaming raise if @raise_faraday_errors raise Gapic::Rest::DeadlineExceededError.wrap_faraday_error e, root_cause: retried_exception rescue ::Faraday::Error => e + log_response method_name, request_id, try_number, e, is_server_streaming next_timeout = get_timeout deadline if check_retry?(next_timeout) && options.retry_policy.call(e) retried_exception = e + try_number += 1 retry end @@ -251,6 +276,54 @@ def check_retry? timeout timeout.positive? end + + def log_request method_name, request_id, try_number, body, metadata + return unless stub_logger + stub_logger.info do |entry| + entry.set_system_name + entry.set_service + entry.set "rpcName", method_name + entry.set "retryAttempt", try_number + entry.set "requestId", request_id + entry.message = "Sending request to #{entry.service}.#{method_name} (try #{try_number})" + end + body = body.to_s + metadata = metadata.to_h rescue {} + return if body.empty? && metadata.empty? + stub_logger.debug do |entry| + entry.set "requestId", request_id + entry.set "request", body + entry.set "headers", metadata + entry.message = "(request payload as JSON)" + end + end + + def log_response method_name, request_id, try_number, response, is_server_streaming + return unless stub_logger + stub_logger.info do |entry| + entry.set_system_name + entry.set_service + entry.set "rpcName", method_name + entry.set "retryAttempt", try_number + entry.set "requestId", request_id + if response.is_a? StandardError + entry.set "exception", response.to_s + entry.message = "Received error for #{entry.service}.#{method_name} (try #{try_number}): #{response}" + elsif is_server_streaming + entry.message = "Receiving stream for #{entry.service}.#{method_name} (try #{try_number})" + else + entry.message = "Received response for #{entry.service}.#{method_name} (try #{try_number})" + end + end + return if is_server_streaming || !response.respond_to?(:body) + body = response.body.to_s + return if body.empty? + stub_logger.debug do |entry| + entry.set "requestId", request_id + entry.set "response", body + entry.message = "(response payload as JSON)" + end + end end end end diff --git a/gapic-common/test/gapic/grpc/channel/channel_test.rb b/gapic-common/test/gapic/grpc/channel/channel_test.rb index 6bc32a561..0f0ab4026 100644 --- a/gapic-common/test/gapic/grpc/channel/channel_test.rb +++ b/gapic-common/test/gapic/grpc/channel/channel_test.rb @@ -48,7 +48,7 @@ def updater_proc end FakeRpcCall = Class.new do - def initialize method_stub + def initialize method_stub, **_kwargs @method_stub = method_stub end diff --git a/gapic-common/test/gapic/grpc/channel_pool/channel_pool_test.rb b/gapic-common/test/gapic/grpc/channel_pool/channel_pool_test.rb index 7247ad15b..337fb573c 100644 --- a/gapic-common/test/gapic/grpc/channel_pool/channel_pool_test.rb +++ b/gapic-common/test/gapic/grpc/channel_pool/channel_pool_test.rb @@ -48,7 +48,7 @@ def updater_proc end FakeRpcCall = Class.new do - def initialize method_stub + def initialize method_stub, **_kwargs @method_stub = method_stub end diff --git a/gapic-common/test/gapic/grpc/logging_test.rb b/gapic-common/test/gapic/grpc/logging_test.rb new file mode 100644 index 000000000..732288828 --- /dev/null +++ b/gapic-common/test/gapic/grpc/logging_test.rb @@ -0,0 +1,229 @@ +# Copyright 2024 Google LLC +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# https://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +require "test_helper" +require "gapic/grpc" +require "google/type/phone_number_pb" + +module MyFakeService + SAMPLE_PROTO_FOR_TESTING = Google::Type::PhoneNumber.new( + short_code: Google::Type::PhoneNumber::ShortCode.new( + region_code: "US", + number: "911" + ) + ) + + SAMPLE_PROTO_FOR_TESTING_2 = Google::Type::PhoneNumber.new( + short_code: Google::Type::PhoneNumber::ShortCode.new( + region_code: "US", + number: "411" + ) + ) + + module FakeServiceModule + class Stub + def initialize *args, **kwargs + end + + def sample_rpc request, **kwargs + self + end + + def execute + SAMPLE_PROTO_FOR_TESTING + end + end + + module Service + def self.service_name + "google.fakeService" + end + end + end + + module FakeStreamingServiceModule + class Stub + def initialize *args, **kwargs + end + + def sample_rpc request, **kwargs + request.each{} + self + end + + def execute + [SAMPLE_PROTO_FOR_TESTING, SAMPLE_PROTO_FOR_TESTING_2] + end + end + + module Service + def self.service_name + "google.fakeStreamingService" + end + end + end +end + +describe Gapic::ServiceStub do + describe "logging" do + let(:creds) { :this_channel_is_insecure } + let(:rpc_name) { "sample_rpc" } + let(:logio) { StringIO.new } + let(:stub_class) { MyFakeService::FakeServiceModule::Stub } + let(:streaming_stub_class) { MyFakeService::FakeStreamingServiceModule::Stub } + let(:sample_request) { MyFakeService::SAMPLE_PROTO_FOR_TESTING } + let(:sample_stream) { [MyFakeService::SAMPLE_PROTO_FOR_TESTING, MyFakeService::SAMPLE_PROTO_FOR_TESTING_2] } + let(:sample_metadata) { { "myheader" => "myvalue" } } + + it "does not log by default" do + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds + assert_nil service_stub.logger + _out, err = capture_subprocess_io do + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + end + assert_equal "", err + end + + it "logs to a default logger when the environment variable is true" do + spoof_logging_env enabled: "true" do + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds + service_stub.logger.reopen logio + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- my_fake_service: Sending request to google.fakeService.sample_rpc (try 1)" + assert_includes logs[1], "DEBUG -- my_fake_service: (request payload as Google::Type::PhoneNumber)" + assert_includes logs[2], "INFO -- my_fake_service: Received response for google.fakeService.sample_rpc (try 1)" + assert_includes logs[3], "DEBUG -- my_fake_service: (response payload as Google::Type::PhoneNumber)" + end + end + + it "does not log when the environment variable is false even with a programmatically given logger" do + spoof_logging_env enabled: "false" do + logger = Logger.new logio, progname: "custom_prog" + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds, logger: logger + assert_nil service_stub.logger + _out, err = capture_subprocess_io do + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + end + assert_equal "", err + end + end + + it "does not log when the environment variable is true but the system does not match" do + spoof_logging_env enabled: "something,something-else" do + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds + assert_nil service_stub.logger + _out, err = capture_subprocess_io do + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + end + assert_equal "", err + end + end + + it "logs logger when the environment variable is true and the system does match" do + spoof_logging_env enabled: "my_fake_service,something-else" do + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds + service_stub.logger.reopen logio + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- my_fake_service: Sending request to google.fakeService.sample_rpc (try 1)" + assert_includes logs[1], "DEBUG -- my_fake_service: (request payload as Google::Type::PhoneNumber)" + assert_includes logs[2], "INFO -- my_fake_service: Received response for google.fakeService.sample_rpc (try 1)" + assert_includes logs[3], "DEBUG -- my_fake_service: (response payload as Google::Type::PhoneNumber)" + end + end + + it "logs to a programmatically given logger" do + logger = Logger.new logio, progname: "custom_prog" + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds, logger: logger + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- custom_prog: Sending request to google.fakeService.sample_rpc (try 1)" + assert_includes logs[1], "DEBUG -- custom_prog: (request payload as Google::Type::PhoneNumber)" + assert_includes logs[2], "INFO -- custom_prog: Received response for google.fakeService.sample_rpc (try 1)" + assert_includes logs[3], "DEBUG -- custom_prog: (response payload as Google::Type::PhoneNumber)" + end + + it "logs in structured format in a google compute environment" do + spoof_logging_env enabled: "all", cloud_run: true do + service_stub = Gapic::ServiceStub.new stub_class, endpoint: "service:port", credentials: creds + service_stub.logger.reopen logio + service_stub.call_rpc rpc_name, sample_request, options: { metadata: sample_metadata } + logs = logio.string.split("\n") + + entry = JSON.load logs[0] + assert_equal "INFO", entry["severity"] + assert_equal "Sending request to google.fakeService.sample_rpc (try 1)", entry["message"] + assert_equal "my_fake_service", entry["system"] + assert_equal "google.fakeService", entry["serviceName"] + assert_equal "sample_rpc", entry["rpcName"] + assert_equal 1, entry["retryAttempt"] + refute_nil entry["timestamp"] + request_id = entry["requestId"] + client_id = entry["clientId"] + refute_nil request_id + refute_nil client_id + assert_equal __FILE__, entry["logging.googleapis.com/sourceLocation"]["file"] + + entry = JSON.load logs[1] + assert_equal "DEBUG", entry["severity"] + assert_equal "(request payload as Google::Type::PhoneNumber)", entry["message"] + refute_nil entry["timestamp"] + assert_equal request_id, entry["requestId"] + assert_equal client_id, entry["clientId"] + assert_equal({"short_code" => {"region_code" => "US", "number" => "911"}}, entry["request"]) + assert_equal sample_metadata, entry["headers"] + assert_equal __FILE__, entry["logging.googleapis.com/sourceLocation"]["file"] + + entry = JSON.load logs[2] + assert_equal "INFO", entry["severity"] + assert_equal "Received response for google.fakeService.sample_rpc (try 1)", entry["message"] + assert_equal "my_fake_service", entry["system"] + assert_equal "google.fakeService", entry["serviceName"] + assert_equal "sample_rpc", entry["rpcName"] + assert_equal 1, entry["retryAttempt"] + refute_nil entry["timestamp"] + assert_equal request_id, entry["requestId"] + assert_equal client_id, entry["clientId"] + assert_equal __FILE__, entry["logging.googleapis.com/sourceLocation"]["file"] + + entry = JSON.load logs[3] + assert_equal "DEBUG", entry["severity"] + assert_equal "(response payload as Google::Type::PhoneNumber)", entry["message"] + refute_nil entry["timestamp"] + assert_equal request_id, entry["requestId"] + assert_equal client_id, entry["clientId"] + assert_equal({"short_code" => {"region_code" => "US", "number" => "911"}}, entry["response"]) + assert_equal __FILE__, entry["logging.googleapis.com/sourceLocation"]["file"] + end + end + + it "logs streaming" do + spoof_logging_env enabled: "true" do + service_stub = Gapic::ServiceStub.new streaming_stub_class, endpoint: "service:port", credentials: creds + service_stub.logger.reopen logio + response = service_stub.call_rpc rpc_name, sample_stream, options: { metadata: sample_metadata } + response.each{} + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- my_fake_service: Sending stream to google.fakeStreamingService.sample_rpc (try 1)" + assert_includes logs[1], "DEBUG -- my_fake_service: (request payload as Google::Type::PhoneNumber)" + assert_includes logs[2], "DEBUG -- my_fake_service: (request payload as Google::Type::PhoneNumber)" + assert_includes logs[3], "INFO -- my_fake_service: Receiving stream for google.fakeStreamingService.sample_rpc (try 1)" + assert_includes logs[4], "DEBUG -- my_fake_service: (response payload as Google::Type::PhoneNumber)" + assert_includes logs[5], "DEBUG -- my_fake_service: (response payload as Google::Type::PhoneNumber)" + assert_equal 6, logs.size + end + end + end +end diff --git a/gapic-common/test/gapic/grpc/rpc_call/raise_test.rb b/gapic-common/test/gapic/grpc/rpc_call/raise_test.rb index 18bc560be..f1a16cabb 100644 --- a/gapic-common/test/gapic/grpc/rpc_call/raise_test.rb +++ b/gapic-common/test/gapic/grpc/rpc_call/raise_test.rb @@ -21,9 +21,7 @@ def test_traps_exception raise GRPC::Unknown end - rpc_call = Gapic::ServiceStub::RpcCall.new( - api_meth_stub - ) + rpc_call = Gapic::ServiceStub::RpcCall.new api_meth_stub assert_raises GRPC::BadStatus do rpc_call.call Object.new @@ -36,9 +34,7 @@ def test_traps_wrapped_exception GRPC::Core::StatusCodes::UNAVAILABLE) end - rpc_call = Gapic::ServiceStub::RpcCall.new( - api_meth_stub - ) + rpc_call = Gapic::ServiceStub::RpcCall.new api_meth_stub assert_raises FakeCodeError do rpc_call.call Object.new @@ -104,9 +100,7 @@ def test_will_rewrap_signet_errors raise GRPC::Unavailable.new(signet_error_text) end - rpc_call = Gapic::ServiceStub::RpcCall.new( - api_meth_stub - ) + rpc_call = Gapic::ServiceStub::RpcCall.new api_meth_stub ex = assert_raises Gapic::GRPC::AuthorizationError do rpc_call.call Object.new diff --git a/gapic-common/test/gapic/grpc/service_stub_test.rb b/gapic-common/test/gapic/grpc/service_stub_test.rb index 0f7583213..be375a48b 100644 --- a/gapic-common/test/gapic/grpc/service_stub_test.rb +++ b/gapic-common/test/gapic/grpc/service_stub_test.rb @@ -58,13 +58,26 @@ def disable_universe_domain_check end end - FakeRpcCall = Class.new do - def initialize method_stub - @method_stub = method_stub - end + module FakeServiceModule + class Stub + def initialize *args, **kwargs + end + + def sample_rpc request, **kwargs + Stub.last_request = request + Stub.call_count += 1 + self + end - def call request, options: nil, &block - @method_stub&.call(request, options) + def execute + Stub.response + end + + class << self + attr_accessor :response + attr_accessor :last_request + attr_accessor :call_count + end end end @@ -72,62 +85,42 @@ def test_with_channel fake_channel = FakeChannel.new channel_pool_config = Gapic::ServiceStub::ChannelPool::Configuration.new channel_pool_config.channel_count = 2 - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", nil], channel_override: fake_channel, interceptors: [] assert_raises ArgumentError do - Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: fake_channel, + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: fake_channel, channel_pool_config: channel_pool_config end - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: fake_channel + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: fake_channel assert service_stub.instance_variable_get(:@channel_pool).nil? - - mock.verify end def test_with_channel_credentials fake_channel_creds = FakeChannelCredentials.new channel_pool_config = Gapic::ServiceStub::ChannelPool::Configuration.new channel_pool_config.channel_count = 2 - mock = Minitest::Mock.new - mock.expect :nil?, false - (1..3).each do - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", fake_channel_creds], channel_args: {}, interceptors: [] - end - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: fake_channel_creds, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, + endpoint: "service:port", credentials: fake_channel_creds, channel_pool_config: channel_pool_config assert service_stub.instance_variable_get(:@grpc_stub).nil? - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: fake_channel_creds + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, + endpoint: "service:port", credentials: fake_channel_creds assert service_stub.instance_variable_get(:@channel_pool).nil? - - mock.verify end def test_with_symbol_credentials creds = :this_channel_is_insecure channel_pool_config = Gapic::ServiceStub::ChannelPool::Configuration.new channel_pool_config.channel_count = 2 - mock = Minitest::Mock.new - mock.expect :nil?, false - (1..3).each do - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", creds], channel_args: {}, interceptors: [] - end - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: creds, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: creds, channel_pool_config: channel_pool_config assert service_stub.instance_variable_get(:@grpc_stub).nil? - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: creds + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: creds assert service_stub.instance_variable_get(:@channel_pool).nil? - - mock.verify end def test_with_credentials @@ -135,21 +128,15 @@ def test_with_credentials GRPC::Core::ChannelCredentials.stub :new, FakeChannelCredentials.method(:new) do channel_pool_config = Gapic::ServiceStub::ChannelPool::Configuration.new channel_pool_config.channel_count = 2 - mock = Minitest::Mock.new - mock.expect :nil?, false - (1..3).each do - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", FakeCallCredentials], channel_args: {}, interceptors: [] - end - - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: FakeCredentials.new, + + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, + endpoint: "service:port", credentials: FakeCredentials.new, channel_pool_config: channel_pool_config assert service_stub.instance_variable_get(:@grpc_stub).nil? - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: FakeCredentials.new + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, + endpoint: "service:port", credentials: FakeCredentials.new assert service_stub.instance_variable_get(:@channel_pool).nil? - - mock.verify end end end @@ -159,23 +146,17 @@ def test_with_proc GRPC::Core::ChannelCredentials.stub :new, FakeChannelCredentials.method(:new) do channel_pool_config = Gapic::ServiceStub::ChannelPool::Configuration.new channel_pool_config.channel_count = 2 - mock = Minitest::Mock.new - mock.expect :nil?, false - (1..3).each do - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", FakeCallCredentials], channel_args: {}, interceptors: [] - end credentials_proc = ->{} - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: credentials_proc, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, + endpoint: "service:port", credentials: credentials_proc, channel_pool_config: channel_pool_config assert service_stub.instance_variable_get(:@grpc_stub).nil? - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: credentials_proc + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, + endpoint: "service:port", credentials: credentials_proc assert service_stub.instance_variable_get(:@channel_pool).nil? - - mock.verify end end end @@ -184,58 +165,31 @@ def test_call_rpc_with_channel_pool creds = :this_channel_is_insecure channel_pool_config = Gapic::ServiceStub::ChannelPool::Configuration.new channel_pool_config.channel_count = 2 - rpc_count = 0 - method_stub = Proc.new do |request, options| - rpc_count += 1 - true - end - mock = Minitest::Mock.new - mock.expect :nil?, false - (1..2).each do - mock.expect :nil?, false - mock.expect :new, mock, ["service:port", creds], channel_args: {}, interceptors: [] - end - mock.expect :method, method_stub, ["sample_rpc"] - - Gapic::ServiceStub::RpcCall.stub :new, FakeRpcCall.method(:new) do - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: creds, - channel_pool_config: channel_pool_config - assert_equal true, service_stub.call_rpc("sample_rpc", nil) - mock.verify - end + FakeServiceModule::Stub.call_count = 0 + FakeServiceModule::Stub.response = :my_response - assert_equal rpc_count, 1 + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: creds, + channel_pool_config: channel_pool_config, logger: nil + assert_equal :my_response, service_stub.call_rpc("sample_rpc", :my_request) + assert_equal :my_request, FakeServiceModule::Stub.last_request + assert_equal 1, FakeServiceModule::Stub.call_count end def test_call_rpc_without_channel_pool creds = :this_channel_is_insecure - rpc_count = 0 - method_stub = Proc.new do |request, options| - rpc_count += 1 - true - end - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :new, mock, ["service:port", creds], channel_args: {}, interceptors: [] - mock.expect :method, method_stub, ["sample_rpc"] - - Gapic::ServiceStub::RpcCall.stub :new, FakeRpcCall.method(:new) do - service_stub = Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: creds - assert_equal true, service_stub.call_rpc("sample_rpc", nil) - mock.verify - end + FakeServiceModule::Stub.call_count = 0 + FakeServiceModule::Stub.response = :my_response - assert_equal rpc_count, 1 - end - - class FakeGrpcStub - def initialize *args, **kwargs - end + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: creds, + logger: nil + assert_equal :my_response, service_stub.call_rpc("sample_rpc", :my_request) + assert_equal :my_request, FakeServiceModule::Stub.last_request + assert_equal 1, FakeServiceModule::Stub.call_count end def test_default_universe_domain creds = FakeCredentials.new - service_stub = Gapic::ServiceStub.new FakeGrpcStub, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint_template: "myservice.$UNIVERSE_DOMAIN$", credentials: creds assert_equal "googleapis.com", service_stub.universe_domain @@ -244,7 +198,7 @@ def test_default_universe_domain def test_custom_universe_domain creds = FakeCredentials.new universe_domain: "myuniverse.com" - service_stub = Gapic::ServiceStub.new FakeGrpcStub, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, universe_domain: "myuniverse.com", endpoint_template: "myservice.$UNIVERSE_DOMAIN$", credentials: creds @@ -257,7 +211,7 @@ def test_universe_domain_env ENV["GOOGLE_CLOUD_UNIVERSE_DOMAIN"] = "myuniverse.com" begin creds = FakeCredentials.new universe_domain: "myuniverse.com" - service_stub = Gapic::ServiceStub.new FakeGrpcStub, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint_template: "myservice.$UNIVERSE_DOMAIN$", credentials: creds assert_equal "myuniverse.com", service_stub.universe_domain @@ -270,7 +224,7 @@ def test_universe_domain_env def test_universe_domain_credentials_mismatch creds = FakeCredentials.new universe_domain: "myuniverse.com" assert_raises Gapic::UniverseDomainMismatch do - Gapic::ServiceStub.new FakeGrpcStub, + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint_template: "myservice.$UNIVERSE_DOMAIN$", credentials: creds end @@ -278,7 +232,7 @@ def test_universe_domain_credentials_mismatch def test_universe_domain_credentials_with_mismatch_disabled creds = FakeCredentialsWithDisabledCheck.new universe_domain: "myuniverse.com" - service_stub = Gapic::ServiceStub.new FakeGrpcStub, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint_template: "myservice.$UNIVERSE_DOMAIN$", credentials: creds assert_equal "googleapis.com", service_stub.universe_domain @@ -286,7 +240,7 @@ def test_universe_domain_credentials_with_mismatch_disabled def test_endpoint_override creds = FakeCredentials.new universe_domain: "myuniverse.com" - service_stub = Gapic::ServiceStub.new FakeGrpcStub, + service_stub = Gapic::ServiceStub.new FakeServiceModule::Stub, universe_domain: "myuniverse.com", endpoint_template: "myservice.$UNIVERSE_DOMAIN$", endpoint: "myservice.otheruniverse.com", diff --git a/gapic-common/test/gapic/grpc/stub_test.rb b/gapic-common/test/gapic/grpc/stub_test.rb index cdeaf0268..b91f3cba4 100644 --- a/gapic-common/test/gapic/grpc/stub_test.rb +++ b/gapic-common/test/gapic/grpc/stub_test.rb @@ -50,52 +50,51 @@ def universe_domain end end + module FakeServiceModule + class Stub + def initialize *args, **kwargs + Stub.args = args + Stub.kwargs = kwargs + end + + class << self + attr_accessor :args + attr_accessor :kwargs + end + end + end + def test_with_channel fake_channel = FakeChannel.new - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", nil], channel_override: fake_channel, interceptors: [] + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: fake_channel - Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: fake_channel - - mock.verify + assert_equal ["service:port", nil], FakeServiceModule::Stub.args + assert_equal fake_channel, FakeServiceModule::Stub.kwargs[:channel_override] end def test_with_channel_credentials fake_channel_creds = FakeChannelCredentials.new - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", fake_channel_creds], channel_args: {}, interceptors: [] - - Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: fake_channel_creds + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: fake_channel_creds - mock.verify + assert_equal ["service:port", fake_channel_creds], FakeServiceModule::Stub.args end def test_with_symbol_credentials creds = :this_channel_is_insecure - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", creds], channel_args: {}, interceptors: [] - - Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: creds + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: creds - mock.verify + assert_equal ["service:port", creds], FakeServiceModule::Stub.args end def test_with_credentials GRPC::Core::CallCredentials.stub :new, FakeCallCredentials.method(:new) do GRPC::Core::ChannelCredentials.stub :new, FakeChannelCredentials.method(:new) do - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", FakeCallCredentials], channel_args: {}, interceptors: [] + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: FakeCredentials.new - Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: FakeCredentials.new - - mock.verify + assert_kind_of FakeCallCredentials, FakeServiceModule::Stub.args.last end end end @@ -103,15 +102,11 @@ def test_with_credentials def test_with_proc GRPC::Core::CallCredentials.stub :new, FakeCallCredentials.method(:new) do GRPC::Core::ChannelCredentials.stub :new, FakeChannelCredentials.method(:new) do - mock = Minitest::Mock.new - mock.expect :nil?, false - mock.expect :new, nil, ["service:port", FakeCallCredentials], channel_args: {}, interceptors: [] - credentials_proc = ->{} - Gapic::ServiceStub.new mock, endpoint: "service:port", credentials: credentials_proc + Gapic::ServiceStub.new FakeServiceModule::Stub, endpoint: "service:port", credentials: credentials_proc - mock.verify + assert_kind_of FakeCallCredentials, FakeServiceModule::Stub.args.last end end end diff --git a/gapic-common/test/gapic/logging_concerns_test.rb b/gapic-common/test/gapic/logging_concerns_test.rb new file mode 100644 index 000000000..b82529f48 --- /dev/null +++ b/gapic-common/test/gapic/logging_concerns_test.rb @@ -0,0 +1,32 @@ +# Copyright 2024 Google LLC +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# https://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +require "test_helper" + +require "gapic/logging_concerns" + +describe Gapic::LoggingConcerns do + describe "random_uuid4" do + it "outputs the correct format" do + output = Gapic::LoggingConcerns.random_uuid4 + assert_match(/[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12}/, output) + end + + it "doesn't repeat" do + output1 = Gapic::LoggingConcerns.random_uuid4 + output2 = Gapic::LoggingConcerns.random_uuid4 + refute_equal output1, output2 + end + end +end diff --git a/gapic-common/test/gapic/rest/client_stub/retry/raise_test.rb b/gapic-common/test/gapic/rest/client_stub/retry/raise_test.rb index 4ff5534d6..be08ef301 100644 --- a/gapic-common/test/gapic/rest/client_stub/retry/raise_test.rb +++ b/gapic-common/test/gapic/rest/client_stub/retry/raise_test.rb @@ -25,6 +25,7 @@ def test_no_retry_when_no_response make_request_proc = lambda do |args| call_count += 1 + nil end options = Gapic::CallOptions.new( diff --git a/gapic-common/test/gapic/rest/client_stub/retry/retry_test.rb b/gapic-common/test/gapic/rest/client_stub/retry/retry_test.rb index 9900d5ad0..921d0947b 100644 --- a/gapic-common/test/gapic/rest/client_stub/retry/retry_test.rb +++ b/gapic-common/test/gapic/rest/client_stub/retry/retry_test.rb @@ -27,7 +27,8 @@ def test_default_retry_strategy inner_responses = Array.new 4 do FakeFaradayError.new(GRPC::Core::StatusCodes::UNAVAILABLE) end - inner_responses += [1729] + final_response = Struct.new(:body).new + inner_responses += [final_response] call_count = 0 make_request_proc = lambda do |args| @@ -63,7 +64,7 @@ def test_default_retry_strategy Kernel.stub :sleep, sleep_proc do ::Process.stub :clock_gettime, time_proc do client_stub.stub :base_make_http_request, make_request_proc do - assert_equal 1729, client_stub.make_get_request(uri: "/foo", options: options) + assert_equal final_response, client_stub.make_get_request(uri: "/foo", options: options) end end end @@ -83,7 +84,8 @@ def test_custom_retry_strategy inner_responses = Array.new 4 do FakeFaradayError.new(GRPC::Core::StatusCodes::UNAVAILABLE) end - inner_responses += [1729] + final_response = Struct.new(:body).new + inner_responses += [final_response] call_count = 0 make_request_proc = lambda do |args| @@ -118,7 +120,7 @@ def test_custom_retry_strategy Kernel.stub :sleep, sleep_proc do client_stub.stub :base_make_http_request, make_request_proc do - assert_equal 1729, client_stub.make_get_request(uri: "/foo", options: options) + assert_equal final_response, client_stub.make_get_request(uri: "/foo", options: options) end end diff --git a/gapic-common/test/gapic/rest/logging_test.rb b/gapic-common/test/gapic/rest/logging_test.rb new file mode 100644 index 000000000..aaa2690cb --- /dev/null +++ b/gapic-common/test/gapic/rest/logging_test.rb @@ -0,0 +1,143 @@ +# Copyright 2024 Google LLC +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# https://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +describe Gapic::Rest::ClientStub do + describe "logging" do + FakeOptions = ::Struct.new :timeout, :on_data do + def eql? other + return false unless other.is_a? FakeOptions + timeout == other.timeout && !!on_data == !!other.on_data + end + alias == eql? + end + + FakeRequest = ::Struct.new :params, :body, :headers, :options do + def initialize + self.options = FakeOptions.new + self.headers = {} + end + + def self.default + req = FakeRequest.new + req.headers = { "Content-Type" => "application/json" } + req + end + end + + def expect_connection client_stub, verb, uri, req + mock = ::Minitest::Mock.new + client_stub.instance_variable_set :@connection, mock + mock.expect verb, nil do |actual_uri, &block| + actual_req = FakeRequest.default + block.call actual_req + (uri == actual_uri && req == actual_req) + end + end + + def make_client_stub logger: :default + ::Gapic::Rest::ClientStub.new endpoint: "google.example.com", + credentials: :dummy_credentials, + logging_system: system_name, + service_name: service_name, + logger: logger + end + + let(:system_name) { "google-example-system" } + let(:service_name) { "google.myapi" } + let(:endpoint) { "google.example.com" } + let(:creds) { :this_channel_is_insecure } + let(:rpc_name) { "sample_rpc" } + let(:logio) { StringIO.new } + + it "does not log by default" do + client_stub = make_client_stub + assert_nil client_stub.logger + mock = expect_connection client_stub, :get, "/foo", FakeRequest.default + _out, err = capture_subprocess_io do + client_stub.make_get_request uri: "/foo", method_name: rpc_name + end + assert_equal "", err + mock.verify + end + + it "logs to a default logger when the environment variable is true" do + spoof_logging_env enabled: "true" do + client_stub = make_client_stub + client_stub.logger.reopen logio + mock = expect_connection client_stub, :get, "/foo", FakeRequest.default + client_stub.make_get_request uri: "/foo", method_name: rpc_name + mock.verify + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- #{system_name}: Sending request to #{service_name}.#{rpc_name} (try 1)" + assert_includes logs[1], "INFO -- #{system_name}: Received response for #{service_name}.#{rpc_name} (try 1)" + end + end + + it "logs to a programmatically given logger" do + logger = Logger.new logio, progname: "custom_prog" + client_stub = make_client_stub logger: logger + mock = expect_connection client_stub, :get, "/foo", FakeRequest.default + client_stub.make_get_request uri: "/foo", method_name: rpc_name + mock.verify + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- custom_prog: Sending request to #{service_name}.#{rpc_name} (try 1)" + assert_includes logs[1], "INFO -- custom_prog: Received response for #{service_name}.#{rpc_name} (try 1)" + end + + it "logs in structured format in a google compute environment" do + spoof_logging_env enabled: "true", cloud_run: true do + client_stub = make_client_stub + client_stub.logger.reopen logio + mock = expect_connection client_stub, :get, "/foo", FakeRequest.default + client_stub.make_get_request uri: "/foo", method_name: rpc_name + mock.verify + logs = logio.string.split("\n") + entry = JSON.load logs[0] + assert_equal "Sending request to #{service_name}.#{rpc_name} (try 1)", entry["message"] + assert_equal system_name, entry["system"] + assert_equal service_name, entry["serviceName"] + assert_equal rpc_name, entry["rpcName"] + assert_equal 1, entry["retryAttempt"] + refute_nil entry["requestId"] + refute_nil entry["timestamp"] + assert_equal __FILE__, entry["logging.googleapis.com/sourceLocation"]["file"] + entry = JSON.load logs[1] + assert_equal "Received response for #{service_name}.#{rpc_name} (try 1)", entry["message"] + assert_equal system_name, entry["system"] + assert_equal service_name, entry["serviceName"] + assert_equal rpc_name, entry["rpcName"] + assert_equal 1, entry["retryAttempt"] + refute_nil entry["requestId"] + refute_nil entry["timestamp"] + assert_equal __FILE__, entry["logging.googleapis.com/sourceLocation"]["file"] + end + end + + it "logs for server streaming" do + spoof_logging_env enabled: "true" do + client_stub = make_client_stub + client_stub.logger.reopen logio + expected_request = FakeRequest.default + expected_request.options.on_data = true + mock = expect_connection client_stub, :get, "/foo", expected_request + client_stub.make_http_request :get, uri: "/foo", body: nil, params: {}, options: nil, method_name: rpc_name, + is_server_streaming: true + mock.verify + logs = logio.string.split("\n") + assert_includes logs[0], "INFO -- #{system_name}: Sending request to #{service_name}.#{rpc_name} (try 1)" + assert_includes logs[1], "INFO -- #{system_name}: Receiving stream for #{service_name}.#{rpc_name} (try 1)" + end + end + end +end diff --git a/gapic-common/test/test_helper.rb b/gapic-common/test/test_helper.rb index f4c281294..b914be635 100644 --- a/gapic-common/test/test_helper.rb +++ b/gapic-common/test/test_helper.rb @@ -21,6 +21,7 @@ require "grpc" require "gapic/common" require "gapic/rest" +require "google/cloud/env" require "google/protobuf/any_pb" require "ostruct" require_relative "./fixtures/fixture_pb" @@ -110,3 +111,19 @@ def make_client_stub numeric_enums: false, raise_faraday_errors: false raise_faraday_errors: raise_faraday_errors end end + +def spoof_logging_env enabled: nil, cloud_run: false + old_enabled = ENV["GOOGLE_SDK_RUBY_LOGGING_GEMS"] + ENV["GOOGLE_SDK_RUBY_LOGGING_GEMS"] = enabled + if cloud_run + Google::Cloud.env.compute_smbios.with_override_product_name "Fake Google" do + Google::Cloud.env.variables.with_backing_data({ "K_SERVICE" => "123" }) do + yield + end + end + else + yield + end +ensure + ENV["GOOGLE_SDK_RUBY_LOGGING_GEMS"] = old_enabled +end