add debug logs

CHANGELOG.md

@@ -2,6 +2,7 @@ Unreleased
 ----------
 * Fixes a bug with `EnsureAuthenticatedLinks` causing deep links to not work [#1549](https://github.com/Shopify/shopify_app/pull/1549)
 * Ensure online token is properly used when using `current_shopify_session` [#1566](https://github.com/Shopify/shopify_app/pull/1566)
+* Added debug logs, you can read more about logging (here)[./docs/logging.md]. [#1545](https://github.com/Shopify/shopify_app/pull/1545)
 * Emit a deprecation notice for wrongly-rescued exceptions [#1530](https://github.com/Shopify/shopify_app/pull/1530)
 * Log a deprecation warning for the use of incompatible controller concerns [#1560](https://github.com/Shopify/shopify_app/pull/1560)
 

README.md

@@ -112,6 +112,7 @@ You can find documentation on gem usage, concepts, mixins, installation, and mor
   * [Testing](/docs/shopify_app/testing.md)
   * [Webhooks](/docs/shopify_app/webhooks.md)
   * [Content Security Policy](/docs/shopify_app/content-security-policy.md)
+  * [Logging](/docs/shopify_app/logging.md)
 
 ### Engine
 

app/controllers/concerns/shopify_app/ensure_authenticated_links.rb

@@ -28,8 +28,8 @@ def splash_page_with_params(params)
     def redirect_to_splash_page
       redirect_to(splash_page)
     rescue ::ShopifyApp::ShopifyDomainNotFound => error
-      Rails.logger.warn("[ShopifyApp::EnsureAuthenticatedLinks] Redirecting to login: [#{error.class}] "\
-        "Could not determine current shop domain")
+      ShopifyApp::Logger.warn("Redirecting to login: [#{error.class}]"\
+        " Could not determine current shop domain")
       redirect_to(ShopifyApp.configuration.login_url)
     end
 

app/controllers/shopify_app/callback_controller.rb

@@ -35,7 +35,10 @@ def callback
         value: auth_result[:cookie].value,
       }
 
-      session[:shopify_user_id] = auth_result[:session].associated_user.id if auth_result[:session].online?
+      if auth_result[:session].online?
+        session[:shopify_user_id] = auth_result[:session].associated_user.id
+        ShopifyApp::Logger.debug("Saving Shopify user ID to cookie")
+      end
 
       if start_user_token_flow?(auth_result[:session])
         return respond_with_user_token_flow

app/controllers/shopify_app/extension_verification_controller.rb

@@ -9,7 +9,10 @@ class ExtensionVerificationController < ActionController::Base
     private
 
     def verify_request
-      head(:unauthorized) unless hmac_valid?(request.body.read)
+      unless hmac_valid?(request.body.read)
+        head(:unauthorized)
+        ShopifyApp::Logger.debug("Extension verification failed due to invalid HMAC")
+      end
     end
   end
 end

app/controllers/shopify_app/sessions_controller.rb

@@ -27,6 +27,8 @@ def top_level_interaction
     def destroy
       reset_session
       flash[:notice] = I18n.t(".logged_out")
+      ShopifyApp::Logger.debug("Session destroyed")
+      ShopifyApp::Logger.debug("Redirecting to #{login_url_with_optional_shop}")
       redirect_to(login_url_with_optional_shop)
     end
 
@@ -38,6 +40,7 @@ def authenticate
       copy_return_to_param_to_session
 
       if embedded_redirect_url?
+        ShopifyApp::Logger.debug("Embedded URL within / authenticate")
         if embedded_param?
           redirect_for_embedded
         else
@@ -52,6 +55,7 @@ def authenticate
 
     def start_oauth
       callback_url = ShopifyApp.configuration.login_callback_url.gsub(%r{^/}, "")
+      ShopifyApp::Logger.debug("Starting OAuth with the following callback URL: #{callback_url}")
 
       auth_attributes = ShopifyAPI::Auth::Oauth.begin_auth(
         shop: sanitized_shop_name,
@@ -65,7 +69,10 @@ def start_oauth
         value: auth_attributes[:cookie].value,
       }
 
-      redirect_to(auth_attributes[:auth_route], allow_other_host: true)
+      auth_route = auth_attributes[:auth_route]
+
+      ShopifyApp::Logger.debug("Redirecting to auth_route - #{auth_route}")
+      redirect_to(auth_route, allow_other_host: true)
     end
 
     def validate_shop_presence
@@ -94,7 +101,9 @@ def top_level?
     end
 
     def redirect_auth_to_top_level
-      fullpage_redirect_to(login_url_with_optional_shop(top_level: true))
+      url = login_url_with_optional_shop(top_level: true)
+      ShopifyApp::Logger.debug("Redirecting to top level - #{url}")
+      fullpage_redirect_to(url)
     end
   end
 end

docs/shopify_app/logging.md

@@ -0,0 +1,21 @@
+# Logging
+
+## Log Levels
+
+There are four log levels with `error` being the most severe.
+
+1. Debug
+2. Info
+3. Warn
+4. Error
+
+## Configuration
+
+The logging is controlled by the `log_level` configuration setting.
+The default log level is `:info`.
+You can disable all logs by setting this to `:off`.
+
+## Upgrading
+
+For a newly-generated app, the `shopify_app` initializer will contain the `log_level` setting.
+If you are upgrading from a previous version of the `shopify_app` gem then you will need to add this manually, otherwise it will default to `:info`.

lib/generators/shopify_app/add_marketing_activity_extension/templates/marketing_activities_controller.rb

@@ -55,7 +55,8 @@ def errors
     request_id = params[:request_id]
     message = params[:message]
 
-    Rails.logger.info("[Marketing Activity App Error Feedback] Request id: #{request_id}, message: #{message}")
+    ShopifyApp::Logger.info("[Marketing Activity App Error Feedback]"\
+      "Request id: #{request_id}, message: #{message}")
 
     render(json: {}, status: :ok)
   end

lib/generators/shopify_app/install/templates/shopify_app.rb.tt

@@ -7,7 +7,7 @@ ShopifyApp.configure do |config|
   config.after_authenticate_job = false
   config.api_version = "<%= @api_version %>"
   config.shop_session_repository = 'Shop'
-
+  config.log_level = :info
   config.reauth_on_access_scope_changes = true
 
   config.api_key = ENV.fetch('SHOPIFY_API_KEY', '').presence

lib/generators/shopify_app/rotate_shopify_token_job/templates/rotate_shopify_token_job.rb

@@ -27,7 +27,7 @@ def perform(params)
     private
 
     def log_error(message)
-      Rails.logger.error(message)
+      ShopifyApp::Logger.error(message)
     end
 
     def no_access_token_error_message

lib/shopify_app.rb

@@ -37,6 +37,8 @@ def self.use_webpacker?
   # errors
   require "shopify_app/errors"
 
+  require "shopify_app/logger"
+
   # controller concerns
   require "shopify_app/controller_concerns/csrf_protection"
   require "shopify_app/controller_concerns/localization"

lib/shopify_app/configuration.rb

@@ -20,6 +20,7 @@ class Configuration
     attr_accessor :api_version
 
     attr_accessor :reauth_on_access_scope_changes
+    attr_accessor :log_level
 
     # customise urls
     attr_accessor :root_url

lib/shopify_app/controller_concerns/ensure_billing.rb

@@ -28,6 +28,7 @@ def check_billing(session = current_shopify_session)
       unless has_payment
         if request.xhr?
           add_top_level_redirection_headers(url: confirmation_url, ignore_response_code: true)
+          ShopifyApp::Logger.debug("Responding with 401 unauthorized")
           head(:unauthorized)
         else
           redirect_to(confirmation_url, allow_other_host: true)
@@ -55,6 +56,7 @@ def has_active_payment?(session)
     end
 
     def has_subscription?(session)
+      ShopifyApp::Logger.debug("Checking if shop has subscription")
       response = run_query(session: session, query: RECURRING_PURCHASES_QUERY)
       subscriptions = response.body["data"]["currentAppInstallation"]["activeSubscriptions"]
 
@@ -70,6 +72,7 @@ def has_subscription?(session)
     end
 
     def has_one_time_payment?(session)
+      ShopifyApp::Logger.debug("Checking if has one time payment")
       purchases = nil
       end_cursor = nil
 

lib/shopify_app/controller_concerns/login_protection.rb

@@ -25,6 +25,7 @@ module LoginProtection
     def activate_shopify_session
       if current_shopify_session.blank?
         signal_access_token_required
+        ShopifyApp::Logger.debug("No session found, redirecting to login")
         return redirect_to_login
       end
 
@@ -36,9 +37,11 @@ def activate_shopify_session
       end
 
       begin
+        ShopifyApp::Logger.debug("Activating Shopify session")
         ShopifyAPI::Context.activate_session(current_shopify_session)
         yield
       ensure
+        ShopifyApp::Logger.debug("Deactivating session")
         ShopifyAPI::Context.deactivate_session
       end
     end
@@ -52,15 +55,18 @@ def current_shopify_session
           is_online: online_token_configured?,
         )
       rescue ShopifyAPI::Errors::CookieNotFoundError
+        ShopifyApp::Logger.info("No cookies have been found - cookie name: #{cookie_name}")
         nil
       rescue ShopifyAPI::Errors::InvalidJwtTokenError
+        ShopifyApp::Logger.info("Invalid JWT token for current Shopify session")
         nil
       end
     end
 
     def login_again_if_different_user_or_shop
       return unless session_id_conflicts_with_params || session_shop_conflicts_with_params
 
+      ShopifyApp::Logger.debug("Clearing session and redirecting to login")
       clear_shopify_session
       redirect_to_login
     end
@@ -78,8 +84,10 @@ def jwt_expire_at
 
     def add_top_level_redirection_headers(url: nil, ignore_response_code: false)
       if request.xhr? && (ignore_response_code || response.code.to_i == 401)
+        ShopifyApp::Logger.debug("Adding top level redirection headers")
         # Make sure the shop is set in the redirection URL
         unless params[:shop]
+          ShopifyApp::Logger.debug("Setting current shop session")
           params[:shop] = if current_shopify_session
             current_shopify_session.shop
           elsif (matches = request.headers["HTTP_AUTHORIZATION"]&.match(/^Bearer (.+)$/))
@@ -90,6 +98,7 @@ def add_top_level_redirection_headers(url: nil, ignore_response_code: false)
 
         url ||= login_url_with_optional_shop
 
+        ShopifyApp::Logger.debug("Setting Reauthorize-Url to #{url}")
         response.set_header("X-Shopify-API-Request-Failure-Reauthorize", "1")
         response.set_header("X-Shopify-API-Request-Failure-Reauthorize-Url", url)
       end
@@ -112,6 +121,7 @@ def host
     def redirect_to_login
       if request.xhr?
         add_top_level_redirection_headers(ignore_response_code: true)
+        ShopifyApp::Logger.debug("Login redirect request is a XHR")
         head(:unauthorized)
       else
         if request.get?
@@ -124,12 +134,15 @@ def redirect_to_login
           query = query.merge(sanitized_params).to_query
         end
         session[:return_to] = query.blank? ? path.to_s : "#{path}?#{query}"
+        ShopifyApp::Logger.debug("Redirecting to #{login_url_with_optional_shop}")
         redirect_to(login_url_with_optional_shop)
       end
     end
 
     def close_session
       clear_shopify_session
+      ShopifyApp::Logger.debug("Closing session")
+      ShopifyApp::Logger.debug("Redirecting to #{login_url_with_optional_shop}")
       redirect_to(login_url_with_optional_shop)
     end
 

lib/shopify_app/controller_concerns/redirect_for_embedded.rb

@@ -16,7 +16,10 @@ def embedded_param?
 
     def redirect_for_embedded
       # Don't actually redirect if we're already in the redirect route - we want the request to reach the FE
-      redirect_to(redirect_uri_for_embedded) unless request.path == ShopifyApp.configuration.embedded_redirect_url
+      unless request.path == ShopifyApp.configuration.embedded_redirect_url
+        ShopifyApp::Logger.debug("Redirecting to #{redirect_uri_for_embedded}")
+        redirect_to(redirect_uri_for_embedded)
+      end
     end
 
     def redirect_uri_for_embedded

lib/shopify_app/controller_concerns/webhook_verification.rb

@@ -14,7 +14,10 @@ module WebhookVerification
 
     def verify_request
       data = request.raw_post
-      return head(:unauthorized) unless hmac_valid?(data)
+      unless hmac_valid?(data)
+        ShopifyApp::Logger.debug("Webhook verification failed - HMAC invalid")
+        head(:unauthorized)
+      end
     end
 
     def shop_domain

lib/shopify_app/logger.rb

@@ -0,0 +1,40 @@
+# frozen_string_literal: true
+
+module ShopifyApp
+  module Logger
+    LOG_LEVELS = { debug: 0, info: 1, warn: 2, error: 3, off: 6 }
+    DEFAULT_LOG_LEVEL = :info
+
+    def self.send_to_logger(log_level, message)
+      return unless enabled_for_log_level?(log_level)
+
+      current_shop = ShopifyAPI::Context.active_session&.shop || "Unknown Shop"
+      message_context = "[ ShopifyApp | #{log_level.to_s.upcase} | #{current_shop} ] #{message}"
+
+      ShopifyAPI::Context.logger.public_send(log_level, message_context)
+    end
+
+    def self.debug(message)
+      send_to_logger(:debug, message)
+    end
+
+    def self.info(message)
+      send_to_logger(:info, message)
+    end
+
+    def self.warn(message)
+      send_to_logger(:warn, message)
+    end
+
+    def self.error(message)
+      send_to_logger(:error, message)
+    end
+
+    def self.enabled_for_log_level?(log_level)
+      raise(ShopifyApp::ConfigurationError,
+        "Invalid Log Level - #{log_level}") unless LOG_LEVELS.keys.include?(log_level)
+
+      LOG_LEVELS[log_level] >= LOG_LEVELS[ShopifyApp.configuration.log_level || DEFAULT_LOG_LEVEL]
+    end
+  end
+end

lib/shopify_app/managers/webhooks_manager.rb

@@ -15,6 +15,8 @@ def queue(shop_domain, shop_token)
       def create_webhooks(session:)
         return unless ShopifyApp.configuration.has_webhooks?
 
+        ShopifyApp::Logger.debug("Creating webhooks #{ShopifyApp.configuration.webhooks}")
+
         ShopifyAPI::Webhooks::Registry.register_all(session: session)
       end
 
@@ -23,12 +25,15 @@ def recreate_webhooks!(session:)
         return unless ShopifyApp.configuration.has_webhooks?
 
         add_registrations
+
+        ShopifyApp::Logger.debug("Recreating webhooks")
         ShopifyAPI::Webhooks::Registry.register_all(session: session)
       end
 
       def destroy_webhooks
         return unless ShopifyApp.configuration.has_webhooks?
 
+        ShopifyApp::Logger.debug("Destroying webhooks")
         ShopifyApp.configuration.webhooks.each do |attributes|
           ShopifyAPI::Webhooks::Registry.unregister(topic: attributes[:topic])
         end
@@ -37,6 +42,7 @@ def destroy_webhooks
       def add_registrations
         return unless ShopifyApp.configuration.has_webhooks?
 
+        ShopifyApp::Logger.debug("Adding registrations to webhooks")
         ShopifyApp.configuration.webhooks.each do |attributes|
           webhook_path = path(attributes)
 

lib/shopify_app/session/jwt.rb

@@ -35,7 +35,7 @@ def set_payload
       payload, _ = parse_token_data(ShopifyApp.configuration&.secret, ShopifyApp.configuration&.old_secret)
       @payload = validate_payload(payload)
     rescue *WARN_EXCEPTIONS => error
-      Rails.logger.warn("[ShopifyApp::JWT] Failed to validate JWT: [#{error.class}] #{error}")
+      ShopifyApp::Logger.warn("Failed to validate JWT: [#{error.class}] #{error}")
       nil
     end