Add Logger to library (#1069)

* move logger over

* fix default log level and tests

* rubocop and sorbet

* add bearer token log

* make enabled_for_log_level and send_to_logger private

* context should have nil shop

* moving log level error to context

* remove setter and add stub to test

* add levels method to logger

* add valid version method for better version comparision

* change log to warn

* log_level as string or symbol

* unit tests for logger

Co-authored-by: Bill Klenotiz <klenotiw@users.noreply.github.com>
Co-authored-by: Nelson Wittwer <nelson.wittwer@shopify.com>

lib/shopify_api/context.rb

@@ -12,7 +12,8 @@ class Context
     @is_private = T.let(false, T::Boolean)
     @private_shop = T.let(nil, T.nilable(String))
     @is_embedded = T.let(true, T::Boolean)
-    @logger = T.let(Logger.new($stdout), Logger)
+    @logger = T.let(::Logger.new($stdout), ::Logger)
+    @log_level = T.let(:info, Symbol)
     @notified_missing_resources_folder = T.let({}, T::Hash[String, T::Boolean])
     @active_session = T.let(Concurrent::ThreadLocalVar.new { nil }, Concurrent::ThreadLocalVar)
     @session_storage = T.let(nil, T.nilable(ShopifyAPI::Auth::SessionStorage))
@@ -32,7 +33,8 @@ class << self
           scope: T.any(T::Array[String], String),
           is_private: T::Boolean,
           is_embedded: T::Boolean,
-          logger: Logger,
+          log_level: T.any(String, Symbol),
+          logger: ::Logger,
           session_storage: T.nilable(ShopifyAPI::Auth::SessionStorage),
           host_name: T.nilable(String),
           host: T.nilable(String),
@@ -48,7 +50,8 @@ def setup(
         scope:,
         is_private:,
         is_embedded:,
-        logger: Logger.new($stdout),
+        log_level: :info,
+        logger: ::Logger.new($stdout),
         session_storage: nil,
         host_name: nil,
         host: ENV["HOST"] || "https://#{host_name}",
@@ -69,16 +72,22 @@ def setup(
         @scope = Auth::AuthScopes.new(scope)
         @is_embedded = is_embedded
         @session_storage = session_storage
-        if @session_storage
-          ::ShopifyAPI::Context.logger.warn("The use of SessionStorage in the API library has been deprecated. " \
-            "The ShopifyAPI will no longer have responsibility for session persistence. " \
-            "Upgrading to `shopify_app` 21.3 will allow you to remove session_storage" \
-            " from the API library Context configuration.")
-        end
         @logger = logger
         @private_shop = private_shop
         @user_agent_prefix = user_agent_prefix
         @old_api_secret_key = old_api_secret_key
+        @log_level = if valid_log_level?(log_level)
+          log_level.to_sym
+        else
+          :info
+        end
+
+        if @session_storage
+          ::ShopifyAPI::Logger.deprecated("The use of SessionStorage in the API library has been deprecated. " \
+            "The ShopifyAPI will no longer have responsibility for session persistence. " \
+            "Upgrading to `shopify_app` 21.3 will allow you to remove session_storage" \
+            " from the API library Context configuration.", "13.0.0")
+        end
 
         load_rest_resources(api_version: api_version)
       end
@@ -120,9 +129,12 @@ def load_rest_resources(api_version:)
       sig { returns(T.nilable(ShopifyAPI::Auth::SessionStorage)) }
       attr_reader :session_storage
 
-      sig { returns(Logger) }
+      sig { returns(::Logger) }
       attr_reader :logger
 
+      sig { returns(Symbol) }
+      attr_reader :log_level
+
       sig { returns(T::Boolean) }
       def private?
         @is_private
@@ -167,6 +179,18 @@ def host_scheme
       def host_name
         T.must(URI(T.must(host)).host)
       end
+
+      private
+
+      sig { params(log_level: T.any(Symbol, String)).returns(T::Boolean) }
+      def valid_log_level?(log_level)
+        return true if ::ShopifyAPI::Logger.levels.include?(log_level.to_sym)
+
+        ShopifyAPI::Logger.warn("#{log_level} is not a valid log_level. "\
+          "Valid options are #{::ShopifyAPI::Logger.levels.join(", ")}")
+
+        false
+      end
     end
   end
 end

lib/shopify_api/errors/feature_deprecated_error.rb

@@ -0,0 +1,9 @@
+# typed: strict
+# frozen_string_literal: true
+
+module ShopifyAPI
+  module Errors
+    class FeatureDeprecatedError < StandardError
+    end
+  end
+end

lib/shopify_api/errors/log_level_not_found_error.rb

@@ -0,0 +1,9 @@
+# typed: strict
+# frozen_string_literal: true
+
+module ShopifyAPI
+  module Errors
+    class LogLevelNotFoundError < StandardError
+    end
+  end
+end

lib/shopify_api/logger.rb

@@ -0,0 +1,82 @@
+# typed: strict
+# frozen_string_literal: true
+
+module ShopifyAPI
+  class Logger
+    LOG_LEVELS = T.let({ debug: 0, info: 1, warn: 2, error: 3, off: 6 }, T::Hash[Symbol, Integer])
+    DEFAULT_LOG_LEVEL = :info
+
+    class << self
+      extend T::Sig
+
+      sig { params(message: String).void }
+      def debug(message)
+        send_to_logger(:debug, message)
+      end
+
+      sig { params(message: String).void }
+      def info(message)
+        send_to_logger(:info, message)
+      end
+
+      sig { params(message: String).void }
+      def warn(message)
+        send_to_logger(:warn, message)
+      end
+
+      sig { params(message: String).void }
+      def error(message)
+        send_to_logger(:error, message)
+      end
+
+      sig { params(message: String, version: String).void }
+      def deprecated(message, version)
+        return unless enabled_for_log_level?(:warn)
+
+        raise Errors::FeatureDeprecatedError unless valid_version(version)
+
+        send_to_logger(:warn, message)
+      end
+
+      sig { returns(T::Array[Symbol]) }
+      def levels
+        LOG_LEVELS.keys
+      end
+
+      private
+
+      sig { params(log_level: Symbol).returns(String) }
+      def context(log_level)
+        current_shop = ShopifyAPI::Context.active_session&.shop
+
+        if current_shop.nil?
+          "[ ShopifyAPI | #{log_level.to_s.upcase} ]"
+        else
+          "[ ShopifyAPI | #{log_level.to_s.upcase} | #{current_shop} ]"
+        end
+      end
+
+      sig { params(log_level: Symbol, message: String).void }
+      def send_to_logger(log_level, message)
+        return unless enabled_for_log_level?(log_level)
+
+        full_message = "#{context(log_level)} #{message}"
+
+        ShopifyAPI::Context.logger.public_send(log_level, full_message)
+      end
+
+      sig { params(log_level: Symbol).returns(T::Boolean) }
+      def enabled_for_log_level?(log_level)
+        T.must(LOG_LEVELS[log_level]) >= T.must(LOG_LEVELS[ShopifyAPI::Context.log_level] ||
+          LOG_LEVELS[DEFAULT_LOG_LEVEL])
+      end
+
+      sig { params(version: String).returns(T::Boolean) }
+      def valid_version(version)
+        current_version = Gem::Version.create(ShopifyAPI::VERSION)
+        deprecate_version = Gem::Version.create(version)
+        current_version < deprecate_version
+      end
+    end
+  end
+end

lib/shopify_api/utils/session_utils.rb

@@ -81,8 +81,10 @@ def current_session_id(auth_header, cookies, online)
           if Context.embedded?
             if auth_header
               matches = auth_header.match(/^Bearer (.+)$/)
-              raise Errors::MissingJwtTokenError,
-                "Missing Bearer token in authorization header" unless matches
+              unless matches
+                ShopifyAPI::Logger.warn("Missing Bearer token in authorization header")
+                raise Errors::MissingJwtTokenError, "Missing Bearer token in authorization header"
+              end
 
               jwt_payload = Auth::JwtPayload.new(T.must(matches[1]))
               shop = jwt_payload.shop

test/context_test.rb

@@ -17,6 +17,7 @@ def setup
         is_private: true,
         is_embedded: true,
         session_storage: ShopifyAPI::Auth::FileSessionStorage.new,
+        log_level: :off,
         logger: Logger.new(writer),
         private_shop: "privateshop.myshopify.com",
         user_agent_prefix: "user_agent_prefix1",
@@ -131,13 +132,33 @@ def test_with_host_name_and_no_host_env
         private_shop: "privateshop.myshopify.com",
         user_agent_prefix: "user_agent_prefix1",
         old_api_secret_key: "old_secret",
+        log_level: :off,
       )
       assert_equal("https", ShopifyAPI::Context.host_scheme)
       assert_equal("https://tunnel-o-security.com", ShopifyAPI::Context.host)
       assert_equal("tunnel-o-security.com", ShopifyAPI::Context.host_name)
       ENV["HOST"] = old_host
     end
 
+    def test_send_a_warning_if_log_level_is_invalid
+      ShopifyAPI::Context.stubs(:log_level).returns(:warn)
+      ShopifyAPI::Logger.expects(:warn).with("not_a_level is not a valid log_level. "\
+        "Valid options are #{::ShopifyAPI::Logger::LOG_LEVELS.keys.join(", ")}")
+      ShopifyAPI::Context.setup(
+        api_key: "",
+        api_secret_key: "",
+        api_version: "unstable",
+        host_name: "",
+        scope: [],
+        is_private: false,
+        is_embedded: true,
+        session_storage: ShopifyAPI::Auth::FileSessionStorage.new,
+        user_agent_prefix: nil,
+        old_api_secret_key: nil,
+        log_level: :not_a_level,
+      )
+    end
+
     def teardown
       ShopifyAPI::Context.deactivate_session
     end
@@ -156,6 +177,7 @@ def clear_context
         session_storage: ShopifyAPI::Auth::FileSessionStorage.new,
         user_agent_prefix: nil,
         old_api_secret_key: nil,
+        log_level: :off,
       )
     end
   end

test/logger_test.rb

@@ -0,0 +1,97 @@
+# typed: true
+# frozen_string_literal: true
+
+require_relative "./test_helper"
+
+module ShopifyAPITest
+  class LoggerTest < Minitest::Test
+    def test_deprecated_should_raise_an_error_if_version_is_lower_or_equal_to_current
+      ShopifyAPI::Context.stubs(:log_level).returns(:warn)
+
+      assert_raises(ShopifyAPI::Errors::FeatureDeprecatedError) do
+        ShopifyAPI::Logger.deprecated("deprecated feature", ShopifyAPI::VERSION)
+      end
+    end
+
+    def test_logging_with_log_levels
+      expected_log_levels = [:debug, :info, :warn, :error]
+      expected_log_levels.each do |log_level|
+        test_when_expected_to_log_with_active_session(log_level)
+        test_when_expected_to_log_without_active_session(log_level)
+      end
+    end
+
+    def test_logging_is_ignored_if_below_log_level
+      loggable_levels = ShopifyAPI::Logger::LOG_LEVELS.keys - [:off]
+      log_level_mapping = {
+        debug: [:debug, :info, :warn, :error],
+        info: [:info, :warn, :error],
+        warn: [:warn, :error],
+        error: [:error],
+        off: [],
+      }
+      stub_active_session(nil)
+      message = "What kind of sushi does a lumberjack order? A log roll"
+
+      log_level_mapping.each do |log_level, expected_loggable_levels|
+        ignored_log_levels = loggable_levels - expected_loggable_levels
+
+        expected_loggable_levels.each do |expected_to_log_level|
+          stub_log_level(log_level)
+          ShopifyAPI::Context.logger.expects(expected_to_log_level)
+          ShopifyAPI::Logger.send(expected_to_log_level, message)
+        end
+
+        ignored_log_levels.each do |ignored_log_level|
+          stub_log_level(log_level)
+          ShopifyAPI::Context.logger.expects(ignored_log_level).never
+          ShopifyAPI::Logger.send(ignored_log_level, message)
+        end
+      end
+    end
+
+    private
+
+    def test_when_expected_to_log_with_active_session(log_level)
+      stub_log_level(log_level)
+      message = "What did the tree say to the lumberjack? Leaf me alone"
+      shop_name = "Little shop of horrors"
+      stub_active_session(shop_name)
+      expected_log = "#{logging_context(log_level, shop_name)} #{message}"
+
+      ShopifyAPI::Context.logger.expects(log_level).with(expected_log)
+      ShopifyAPI::Logger.public_send(log_level, message)
+    end
+
+    def test_when_expected_to_log_without_active_session(log_level)
+      stub_log_level(log_level)
+      message = "What did the tree say to the lumberjack? Leaf me alone"
+      stub_active_session(nil)
+      expected_log = "#{logging_context(log_level)} #{message}"
+
+      ShopifyAPI::Context.logger.expects(log_level).with(expected_log)
+      ShopifyAPI::Logger.public_send(log_level, message)
+    end
+
+    def stub_log_level(log_level)
+      ShopifyAPI::Context.expects(:log_level).returns(log_level)
+    end
+
+    def stub_active_session(shop_name)
+      if shop_name
+        session = ShopifyAPI::Auth::Session.new(shop: shop_name)
+        ShopifyAPI::Context.stubs(:active_session).returns(session)
+      else
+        ShopifyAPI::Context.stubs(:active_session).returns(nil)
+      end
+    end
+
+    def logging_context(log_level, shop_name = nil)
+      if shop_name
+        "[ ShopifyAPI | #{log_level.to_s.upcase} | #{shop_name} ]"
+      else
+        "[ ShopifyAPI | #{log_level.to_s.upcase} ]"
+      end
+    end
+  end
+end

test/test_helper.rb

@@ -34,6 +34,7 @@ def setup
           session_storage: TestHelpers::FakeSessionStorage.new,
           user_agent_prefix: nil,
           old_api_secret_key: nil,
+          log_level: :off,
         )
       end
 
@@ -80,6 +81,7 @@ def modify_context(
           private_shop: private_shop != "do-not-set" ? private_shop : ShopifyAPI::Context.private_shop,
           user_agent_prefix: user_agent_prefix ? user_agent_prefix : ShopifyAPI::Context.user_agent_prefix,
           old_api_secret_key: old_api_secret_key ? old_api_secret_key : ShopifyAPI::Context.old_api_secret_key,
+          log_level: :off,
         )
       end
     end