From 890b3031b5d75c3d8093eca51f13b1eac9db385f Mon Sep 17 00:00:00 2001 From: Robert Mosolgo Date: Thu, 19 Oct 2023 16:08:10 -0400 Subject: [PATCH 1/4] Add Query#logger --- guides/queries/logging.md | 22 +++++++++++ lib/graphql/query.rb | 10 +++++ lib/graphql/query/context.rb | 2 +- lib/graphql/schema.rb | 19 ++++++++++ lib/graphql/schema/warden.rb | 9 ++++- spec/graphql/logger_spec.rb | 73 ++++++++++++++++++++++++++++++++++++ 6 files changed, 133 insertions(+), 2 deletions(-) create mode 100644 guides/queries/logging.md create mode 100644 spec/graphql/logger_spec.rb diff --git a/guides/queries/logging.md b/guides/queries/logging.md new file mode 100644 index 0000000000..75e5d9ec35 --- /dev/null +++ b/guides/queries/logging.md @@ -0,0 +1,22 @@ +--- +layout: guide +doc_stub: false +search: true +section: Queries +title: Logging +desc: Development output from GraphQL-Ruby +index: 12 +--- + +At runtime, GraphQL-Ruby will output debug information using {{ "GraphQL::Query.logger" | api_doc }}. By default, this uses `Rails.logger`. To see output, make sure `config.log_level = :debug` is set. (This information isn't meant for production logs.) + +You can configure a custom logger with {{ "GraphQL::Schema.default_logger" | api_doc }}, for example: + +```ruby +class MySchema < GraphQL::Schema + # This logger will be used by queries during execution: + default_logger MyCustomLogger.new +end +``` + +You can also pass `context[:logger]` to provide a logger during execution. diff --git a/lib/graphql/query.rb b/lib/graphql/query.rb index 09b21ad941..47d5931e20 100644 --- a/lib/graphql/query.rb +++ b/lib/graphql/query.rb @@ -162,6 +162,14 @@ def initialize(schema, query_string = nil, query: nil, document: nil, context: n @result_values = nil @executed = false + + @logger = if context && context[:logger] == false + Logger.new(IO::NULL) + elsif context && (l = context[:logger]) + l + else + schema.default_logger + end end # If a document was provided to `GraphQL::Schema#execute` instead of the raw query string, we will need to get it from the document @@ -369,6 +377,8 @@ def after_lazy(value, &block) end end + attr_reader :logger + private def find_operation(operations, operation_name) diff --git a/lib/graphql/query/context.rb b/lib/graphql/query/context.rb index d370a0b9d2..4670cff44b 100644 --- a/lib/graphql/query/context.rb +++ b/lib/graphql/query/context.rb @@ -114,7 +114,7 @@ def []=(key, value) @provided_values[key] = value end - def_delegators :@query, :trace, :interpreter? + def_delegators :@query, :trace, :interpreter?, :logger RUNTIME_METADATA_KEYS = Set.new([:current_object, :current_arguments, :current_field, :current_path]) # @!method []=(key, value) diff --git a/lib/graphql/schema.rb b/lib/graphql/schema.rb index 2d54108f95..11acce33af 100644 --- a/lib/graphql/schema.rb +++ b/lib/graphql/schema.rb @@ -1,4 +1,5 @@ # frozen_string_literal: true +require "logger" require "graphql/schema/addition" require "graphql/schema/always_visible" require "graphql/schema/base_64_encoder" @@ -835,6 +836,24 @@ def default_analysis_engine end end + def default_logger(new_default_logger = NOT_CONFIGURED) + if NOT_CONFIGURED.equal?(new_default_logger) + if defined?(@default_logger) + @default_logger + elsif superclass.respond_to?(:default_logger) + superclass.default_logger + elsif defined?(Rails) + Rails.logger + else + Logger.new($stdout) + end + elsif new_default_logger == nil + @default_logger = Logger.new(IO::NULL) + else + @default_logger = new_default_logger + end + end + def context_class(new_context_class = nil) if new_context_class @context_class = new_context_class diff --git a/lib/graphql/schema/warden.rb b/lib/graphql/schema/warden.rb index 624fadf278..ffd911ed73 100644 --- a/lib/graphql/schema/warden.rb +++ b/lib/graphql/schema/warden.rb @@ -291,7 +291,14 @@ def visible_and_reachable_type?(type_defn) if type_defn.kind.union? possible_types(type_defn).any? && (referenced?(type_defn) || orphan_type?(type_defn)) elsif type_defn.kind.interface? - possible_types(type_defn).any? + if possible_types(type_defn).any? + true + else + if @context.respond_to?(:logger) + @context.logger.debug { "Interface `#{type_defn.graphql_name}` hidden because it has no visible implementors" } + end + false + end else if referenced?(type_defn) true diff --git a/spec/graphql/logger_spec.rb b/spec/graphql/logger_spec.rb new file mode 100644 index 0000000000..ce8d7d6494 --- /dev/null +++ b/spec/graphql/logger_spec.rb @@ -0,0 +1,73 @@ +# frozen_string_literal: true +require "spec_helper" + +describe "Logger" do + describe "Schema.default_logger" do + if defined?(Rails) + it "When Rails is present, returns the Rails logger" do + assert_equal Rails.logger, GraphQL::Schema.default_logger + end + else + it "Without Rails, returns a new logger" do + assert_instance_of Logger, GraphQL::Schema.default_logger + end + end + + it "can be overridden" do + new_logger = Logger.new($stdout) + schema = Class.new(GraphQL::Schema) do + default_logger(new_logger) + end + assert_equal new_logger, schema.default_logger + end + + it "can be set to a null logger with nil" do + schema = Class.new(GraphQL::Schema) + schema.default_logger(nil) + nil_logger = schema.default_logger + std_out, std_err = capture_io do + nil_logger.error("Blah") + nil_logger.warn("Something") + nil_logger.log("Hi") + end + assert_equal "", std_out + assert_equal "", std_err + end + end + + describe "during execution" do + + class LoggerSchema < GraphQL::Schema + LOG_STRING = StringIO.new + LOGGER = Logger.new(LOG_STRING) + LOGGER.level = :debug + + module Node + include GraphQL::Schema::Interface + field :id, ID + end + + class Query < GraphQL::Schema::Object + field :node, Node do + argument :id, ID + end + + def node(id:) + + end + end + query(Query) + default_logger(LOGGER) + end + + before do + LoggerSchema::LOG_STRING.truncate(0) + end + + it "logs about hidden interfaces with no implementations" do + res = LoggerSchema.execute("{ node(id: \"5\") { id } }") + assert_equal ["Field 'node' doesn't exist on type 'Query'"], res["errors"].map { |err| err["message"] } + assert_includes LoggerSchema::LOG_STRING.string, "Interface `Node` hidden because it has no visible implementors" + end + end +end From fe1816e25e495873c182a67096e53b9b05e6a0b6 Mon Sep 17 00:00:00 2001 From: Robert Mosolgo Date: Thu, 19 Oct 2023 16:33:41 -0400 Subject: [PATCH 2/4] Fix tests --- lib/graphql/query/context.rb | 6 +++++- lib/graphql/schema/warden.rb | 4 ++-- spec/graphql/authorization_spec.rb | 1 + spec/graphql/dataloader/async_dataloader_spec.rb | 14 +++++++------- spec/graphql/schema/directive/flagged_spec.rb | 1 + spec/graphql/schema/warden_spec.rb | 2 ++ 6 files changed, 18 insertions(+), 10 deletions(-) diff --git a/lib/graphql/query/context.rb b/lib/graphql/query/context.rb index 4670cff44b..e9a07aa0f6 100644 --- a/lib/graphql/query/context.rb +++ b/lib/graphql/query/context.rb @@ -114,7 +114,7 @@ def []=(key, value) @provided_values[key] = value end - def_delegators :@query, :trace, :interpreter?, :logger + def_delegators :@query, :trace, :interpreter? RUNTIME_METADATA_KEYS = Set.new([:current_object, :current_arguments, :current_field, :current_path]) # @!method []=(key, value) @@ -237,6 +237,10 @@ def namespace?(ns) @storage.key?(ns) end + def logger + @query && @query.logger + end + def inspect "#" end diff --git a/lib/graphql/schema/warden.rb b/lib/graphql/schema/warden.rb index ffd911ed73..e03db4e83c 100644 --- a/lib/graphql/schema/warden.rb +++ b/lib/graphql/schema/warden.rb @@ -294,8 +294,8 @@ def visible_and_reachable_type?(type_defn) if possible_types(type_defn).any? true else - if @context.respond_to?(:logger) - @context.logger.debug { "Interface `#{type_defn.graphql_name}` hidden because it has no visible implementors" } + if @context.respond_to?(:logger) && (logger = @context.logger) + logger.debug { "Interface `#{type_defn.graphql_name}` hidden because it has no visible implementors" } end false end diff --git a/spec/graphql/authorization_spec.rb b/spec/graphql/authorization_spec.rb index fee0731e14..aeebd076c4 100644 --- a/spec/graphql/authorization_spec.rb +++ b/spec/graphql/authorization_spec.rb @@ -339,6 +339,7 @@ class Schema < GraphQL::Schema query(Query) mutation(Mutation) directive(Nothing) + default_logger(nil) lazy_resolve(Box, :value) diff --git a/spec/graphql/dataloader/async_dataloader_spec.rb b/spec/graphql/dataloader/async_dataloader_spec.rb index cd1704e603..4cbbe15738 100644 --- a/spec/graphql/dataloader/async_dataloader_spec.rb +++ b/spec/graphql/dataloader/async_dataloader_spec.rb @@ -240,13 +240,13 @@ def self.included(child_class) include AsyncDataloaderAssertions end - if RUBY_ENGINE == "ruby" && !ENV["GITHUB_ACTIONS"] - describe "With libev_scheduler" do - require "libev_scheduler" - let(:scheduler_class) { Libev::Scheduler } - include AsyncDataloaderAssertions - end - end + # if RUBY_ENGINE == "ruby" && !ENV["GITHUB_ACTIONS"] + # describe "With libev_scheduler" do + # require "libev_scheduler" + # let(:scheduler_class) { Libev::Scheduler } + # include AsyncDataloaderAssertions + # end + # end describe "with evt" do require "evt" diff --git a/spec/graphql/schema/directive/flagged_spec.rb b/spec/graphql/schema/directive/flagged_spec.rb index 251a9ad8aa..3ab2fc354e 100644 --- a/spec/graphql/schema/directive/flagged_spec.rb +++ b/spec/graphql/schema/directive/flagged_spec.rb @@ -40,6 +40,7 @@ def santas_workshop; true; end query(Query) orphan_types(PolarBear, Penguin) + default_logger(nil) def self.resolve_type(abs_type, obj, ctx) case obj[:type] diff --git a/spec/graphql/schema/warden_spec.rb b/spec/graphql/schema/warden_spec.rb index 37ebb4c9a8..c39f25e5f1 100644 --- a/spec/graphql/schema/warden_spec.rb +++ b/spec/graphql/schema/warden_spec.rb @@ -500,6 +500,7 @@ def error_messages(query_result) | schema = GraphQL::Schema.from_definition(sdl) + schema.default_logger(nil) schema.define_singleton_method(:visible?) do |member, ctx| super(member, ctx) && (ctx[:hiding] ? member.graphql_name != "Repository" : true) end @@ -598,6 +599,7 @@ def self.visible?(member, context) " schema = GraphQL::Schema.from_definition(sdl) + schema.default_logger(nil) schema.define_singleton_method(:visible?) do |member, context| res = super(member, context) if res && context[:except] From 087fd75629a771f450b877cd30d1b99181a9d587 Mon Sep 17 00:00:00 2001 From: Robert Mosolgo Date: Thu, 19 Oct 2023 16:37:46 -0400 Subject: [PATCH 3/4] Fix logger usage --- spec/graphql/logger_spec.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/graphql/logger_spec.rb b/spec/graphql/logger_spec.rb index ce8d7d6494..bc96ecde9b 100644 --- a/spec/graphql/logger_spec.rb +++ b/spec/graphql/logger_spec.rb @@ -28,7 +28,7 @@ std_out, std_err = capture_io do nil_logger.error("Blah") nil_logger.warn("Something") - nil_logger.log("Hi") + nil_logger.error("Hi") end assert_equal "", std_out assert_equal "", std_err From 16d73b6d737f520954753556ca1c1fe7dacaece7 Mon Sep 17 00:00:00 2001 From: Robert Mosolgo Date: Fri, 20 Oct 2023 11:10:31 -0400 Subject: [PATCH 4/4] Make the logger silent by default --- lib/graphql/schema.rb | 4 +- spec/graphql/authorization_spec.rb | 1 - spec/graphql/logger_spec.rb | 51 ++++++++++++------- spec/graphql/schema/directive/flagged_spec.rb | 1 - spec/graphql/schema/warden_spec.rb | 2 - 5 files changed, 35 insertions(+), 24 deletions(-) diff --git a/lib/graphql/schema.rb b/lib/graphql/schema.rb index 11acce33af..393282038d 100644 --- a/lib/graphql/schema.rb +++ b/lib/graphql/schema.rb @@ -845,7 +845,9 @@ def default_logger(new_default_logger = NOT_CONFIGURED) elsif defined?(Rails) Rails.logger else - Logger.new($stdout) + def_logger = Logger.new($stdout) + def_logger.info! # It doesn't output debug info by default + def_logger end elsif new_default_logger == nil @default_logger = Logger.new(IO::NULL) diff --git a/spec/graphql/authorization_spec.rb b/spec/graphql/authorization_spec.rb index aeebd076c4..fee0731e14 100644 --- a/spec/graphql/authorization_spec.rb +++ b/spec/graphql/authorization_spec.rb @@ -339,7 +339,6 @@ class Schema < GraphQL::Schema query(Query) mutation(Mutation) directive(Nothing) - default_logger(nil) lazy_resolve(Box, :value) diff --git a/spec/graphql/logger_spec.rb b/spec/graphql/logger_spec.rb index bc96ecde9b..627769dbee 100644 --- a/spec/graphql/logger_spec.rb +++ b/spec/graphql/logger_spec.rb @@ -36,38 +36,51 @@ end describe "during execution" do + module LoggerTest + class DefaultLoggerSchema < GraphQL::Schema + module Node + include GraphQL::Schema::Interface + field :id, ID + end - class LoggerSchema < GraphQL::Schema - LOG_STRING = StringIO.new - LOGGER = Logger.new(LOG_STRING) - LOGGER.level = :debug + class Query < GraphQL::Schema::Object + field :node, Node do + argument :id, ID + end - module Node - include GraphQL::Schema::Interface - field :id, ID - end + def node(id:) - class Query < GraphQL::Schema::Object - field :node, Node do - argument :id, ID + end end + query(Query) + end - def node(id:) - - end + class CustomLoggerSchema < DefaultLoggerSchema + LOG_STRING = StringIO.new + LOGGER = Logger.new(LOG_STRING) + LOGGER.level = :debug + default_logger(LOGGER) end - query(Query) - default_logger(LOGGER) end before do - LoggerSchema::LOG_STRING.truncate(0) + LoggerTest::CustomLoggerSchema::LOG_STRING.truncate(0) end it "logs about hidden interfaces with no implementations" do - res = LoggerSchema.execute("{ node(id: \"5\") { id } }") + res = LoggerTest::CustomLoggerSchema.execute("{ node(id: \"5\") { id } }") + assert_equal ["Field 'node' doesn't exist on type 'Query'"], res["errors"].map { |err| err["message"] } + assert_includes LoggerTest::CustomLoggerSchema::LOG_STRING.string, "Interface `Node` hidden because it has no visible implementors" + end + + it "doesn't print messages by default" do + res = nil + stdout, stderr = capture_io do + res = LoggerTest::DefaultLoggerSchema.execute("{ node(id: \"5\") { id } }") + end assert_equal ["Field 'node' doesn't exist on type 'Query'"], res["errors"].map { |err| err["message"] } - assert_includes LoggerSchema::LOG_STRING.string, "Interface `Node` hidden because it has no visible implementors" + assert_equal "", stdout + assert_equal "", stderr end end end diff --git a/spec/graphql/schema/directive/flagged_spec.rb b/spec/graphql/schema/directive/flagged_spec.rb index 3ab2fc354e..251a9ad8aa 100644 --- a/spec/graphql/schema/directive/flagged_spec.rb +++ b/spec/graphql/schema/directive/flagged_spec.rb @@ -40,7 +40,6 @@ def santas_workshop; true; end query(Query) orphan_types(PolarBear, Penguin) - default_logger(nil) def self.resolve_type(abs_type, obj, ctx) case obj[:type] diff --git a/spec/graphql/schema/warden_spec.rb b/spec/graphql/schema/warden_spec.rb index c39f25e5f1..37ebb4c9a8 100644 --- a/spec/graphql/schema/warden_spec.rb +++ b/spec/graphql/schema/warden_spec.rb @@ -500,7 +500,6 @@ def error_messages(query_result) | schema = GraphQL::Schema.from_definition(sdl) - schema.default_logger(nil) schema.define_singleton_method(:visible?) do |member, ctx| super(member, ctx) && (ctx[:hiding] ? member.graphql_name != "Repository" : true) end @@ -599,7 +598,6 @@ def self.visible?(member, context) " schema = GraphQL::Schema.from_definition(sdl) - schema.default_logger(nil) schema.define_singleton_method(:visible?) do |member, context| res = super(member, context) if res && context[:except]