Merge pull request #4674 from rmosolgo/query-logger

Add Query#logger

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.

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)

lib/graphql/query/context.rb

@@ -237,6 +237,10 @@ def namespace?(ns)
         @storage.key?(ns)
       end
 
+      def logger
+        @query && @query.logger
+      end
+
       def inspect
         "#<Query::Context ...>"
       end

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,26 @@ 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
+            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)
+        else
+          @default_logger = new_default_logger
+        end
+      end
+
       def context_class(new_context_class = nil)
         if new_context_class
           @context_class = new_context_class

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) && (logger = @context.logger)
+                logger.debug { "Interface `#{type_defn.graphql_name}` hidden because it has no visible implementors" }
+              end
+              false
+            end
           else
             if referenced?(type_defn)
               true

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"

spec/graphql/logger_spec.rb

@@ -0,0 +1,86 @@
+# 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.error("Hi")
+      end
+      assert_equal "", std_out
+      assert_equal "", std_err
+    end
+  end
+
+  describe "during execution" do
+    module LoggerTest
+      class DefaultLoggerSchema < GraphQL::Schema
+        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)
+      end
+
+      class CustomLoggerSchema < DefaultLoggerSchema
+        LOG_STRING = StringIO.new
+        LOGGER = Logger.new(LOG_STRING)
+        LOGGER.level = :debug
+        default_logger(LOGGER)
+      end
+    end
+
+    before do
+      LoggerTest::CustomLoggerSchema::LOG_STRING.truncate(0)
+    end
+
+    it "logs about hidden interfaces with no implementations" do
+      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_equal "", stdout
+      assert_equal "", stderr
+    end
+  end
+end