Renaming some Controller Concerns

README.md

@@ -110,6 +110,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/authenticated.rb

@@ -2,18 +2,11 @@
 
 module ShopifyApp
   module Authenticated
+    extend ShopifyApp::EnsureHasSession
     extend ActiveSupport::Concern
 
     included do
-      include ShopifyApp::Localization
-      include ShopifyApp::LoginProtection
-      include ShopifyApp::CsrfProtection
-      include ShopifyApp::EmbeddedApp
-      include ShopifyApp::EnsureBilling
-
-      before_action :login_again_if_different_user_or_shop
-      around_action :activate_shopify_session
-      after_action :add_top_level_redirection_headers
+      ShopifyApp::Logger.deprecated("Authenticated has been renamed to EnsureHasSession")
     end
   end
 end

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("[ShopifyApp::EnsureAuthenticatedLinks] Redirecting to login: [#{error.class}]"\
+        " Could not determine current shop domain")
       redirect_to(ShopifyApp.configuration.login_url)
     end
 

app/controllers/concerns/shopify_app/ensure_has_session.rb

@@ -0,0 +1,20 @@
+# frozen_string_literal: true
+
+module ShopifyApp
+  module EnsureHasSession
+    extend ActiveSupport::Concern
+
+    included do
+      include ShopifyApp::Localization
+      include ShopifyApp::LoginProtection
+      include ShopifyApp::CsrfProtection
+      include ShopifyApp::EmbeddedApp
+      include ShopifyApp::EnsureBilling
+
+      before_action :login_again_if_different_user_or_shop
+      around_action :activate_shopify_session
+      after_action :add_top_level_redirection_headers
+    end
+  end
+end
+

app/controllers/concerns/shopify_app/ensure_installed.rb

@@ -0,0 +1,48 @@
+# frozen_string_literal: true
+
+module ShopifyApp
+  module EnsureInstalled
+    extend ActiveSupport::Concern
+    include ShopifyApp::RedirectForEmbedded
+
+    included do
+      before_action :check_shop_domain
+      before_action :check_shop_known
+    end
+
+    def current_shopify_domain
+      return if params[:shop].blank?
+
+      @shopify_domain ||= ShopifyApp::Utils.sanitize_shop_domain(params[:shop])
+    end
+
+    private
+
+    def check_shop_domain
+      redirect_to(ShopifyApp.configuration.login_url) unless current_shopify_domain
+    end
+
+    def check_shop_known
+      @shop = SessionRepository.retrieve_shop_session_by_shopify_domain(current_shopify_domain)
+      unless @shop
+        if embedded_param?
+          redirect_for_embedded
+        else
+          redirect_to(shop_login)
+        end
+      end
+    end
+
+    def shop_login
+      url = URI(ShopifyApp.configuration.login_url)
+
+      url.query = URI.encode_www_form(
+        shop: params[:shop],
+        host: params[:host],
+        return_to: request.fullpath,
+      )
+
+      url.to_s
+    end
+  end
+end

app/controllers/concerns/shopify_app/require_known_shop.rb

@@ -6,6 +6,7 @@ module RequireKnownShop
     include ShopifyApp::RedirectForEmbedded
 
     included do
+      # ShopifyApp::Logger.deprecated("RequireKnownShop has been renamed to EnsureInstalled")
       before_action :check_shop_domain
       before_action :check_shop_known
     end

app/controllers/shopify_app/callback_controller.rb

@@ -28,7 +28,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("Setting :shopify_user_id to Rails 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 - 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,12 +40,15 @@ def authenticate
       copy_return_to_param_to_session
 
       if embedded_redirect_url?
+        ShopifyApp::Logger.debug("Embedded URL within / authenticate")
         if embedded_param?
+          ShopifyApp::Logger.debug("Embedded param")
           redirect_for_embedded
         else
           start_oauth
         end
       elsif top_level?
+        ShopifyApp::Logger.debug("Top level redirect")
         start_oauth
       else
         redirect_auth_to_top_level
@@ -52,6 +57,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,6 +71,7 @@ def start_oauth
         value: auth_attributes[:cookie].value,
       }
 
+      ShopifyApp::Logger.debug("Redirecting to auth_route - #{auth_attributes[:auth_route]}")
       redirect_to(auth_attributes[:auth_route], allow_other_host: true)
     end
 
@@ -94,6 +101,7 @@ def top_level?
     end
 
     def redirect_auth_to_top_level
+      ShopifyApp::Logger.debug("Redirecting to top level - #{login_url_with_optional_shop(top_level: true)}")
       fullpage_redirect_to(login_url_with_optional_shop(top_level: true))
     end
   end

docs/shopify_app/logging.md

@@ -0,0 +1,14 @@
+# Logging
+
+## Log Levels
+
+1. Debug
+2. Info
+3. Warn
+4. Error
+
+We have four log levels with `error` being the most severe.
+
+## Configuration
+
+You can configure your log level by changing your `SHOPIFY_LOG_LEVEL` environment variable. If `SHOPIFY_LOG_LEVEL` is not set the configuration file with default to `info`. To turn off all shopify_app logs you can change this environment variable to `off`.

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

@@ -13,6 +13,8 @@ ShopifyApp.configure do |config|
   config.api_key = ENV.fetch('SHOPIFY_API_KEY', '').presence
   config.secret = ENV.fetch('SHOPIFY_API_SECRET', '').presence
 
+  config.log_level = ENV["SHOPIFY_LOG_LEVEL"]&.to_sym || :info
+
   # You may want to charge merchants for using your app. Setting the billing configuration will cause the Authenticated
   # controller concern to check that the session is for a merchant that has an active one-time payment or subscription.
   # If no payment is found, it starts off the process and sends the merchant to a confirmation URL so that they can

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,9 @@ def self.use_webpacker?
   # errors
   require "shopify_app/errors"
 
+  # logger
+  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("Setting 401 from EnsureBilling")
           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("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("Has One Time Payment")
       purchases = nil
       end_cursor = nil
 
@@ -163,6 +166,7 @@ def recurring?
     def run_query(session:, query:, variables: nil)
       client = ShopifyAPI::Clients::Graphql::Admin.new(session: session)
 
+      ShopifyApp::Logger.debug("Client query - Query: #{query}, Variables: #{variables} ")
       response = client.query(query: query, variables: variables)
 
       raise BillingError.new("Error while billing the store", []) unless response.ok?

lib/shopify_app/controller_concerns/login_protection.rb

@@ -16,8 +16,11 @@ module LoginProtection
     ACCESS_TOKEN_REQUIRED_HEADER = "X-Shopify-API-Request-Failure-Unauthorized"
 
     def activate_shopify_session
+      ShopifyApp::Logger.debug("Activating Shopify Session")
+
       if current_shopify_session.blank?
         signal_access_token_required
+        ShopifyApp::Logger.debug("No session found for request in JWT or cookie.")
         return redirect_to_login
       end
 
@@ -32,6 +35,7 @@ def activate_shopify_session
         ShopifyAPI::Context.activate_session(current_shopify_session)
         yield
       ensure
+        ShopifyApp::Logger.info("Deactivating Session")
         ShopifyAPI::Context.deactivate_session
       end
     end
@@ -45,8 +49,10 @@ def current_shopify_session
           is_online: online_token_configured?,
         )
       rescue ShopifyAPI::Errors::CookieNotFoundError
+        ShopifyApp::Logger.info("CookiesNotFound for current shopify session")
         nil
       rescue ShopifyAPI::Errors::InvalidJwtTokenError
+        ShopifyApp::Logger.info("Invalid Jwt token for current shopify session")
         nil
       end
     end
@@ -55,6 +61,7 @@ def login_again_if_different_user_or_shop
       return unless session_id_conflicts_with_params || session_shop_conflicts_with_params
 
       clear_shopify_session
+      ShopifyApp::Logger.debug("session id or session shop conflicts with params")
       redirect_to_login
     end
 
@@ -71,8 +78,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 (.+)$/))
@@ -83,6 +92,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
@@ -105,6 +115,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?
@@ -117,12 +128,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,6 +14,7 @@ module WebhookVerification
 
     def verify_request
       data = request.raw_post
+      ShopifyApp::Logger.debug("Webhook verification failed - HMAC invalid")
       return head(:unauthorized) unless hmac_valid?(data)
     end