Merge pull request #3557 from AlchemyCMS/alchemy-logger-proper

tvdeyen · web-flow · commit c2a84aab4123 · 2026-01-09T14:41:32.000+01:00
Use tagged logging in Alchemy:Logger
diff --git a/app/components/alchemy/ingredients/base_editor.rb b/app/components/alchemy/ingredients/base_editor.rb
@@ -114,7 +114,7 @@ def warnings
         return unless has_warnings?
 
         if definition.blank?
-          Logger.warn("ingredient #{role} is missing its definition", caller(1..1))
+          Logger.warn("ingredient '#{role}' is missing its definition! Please check your element definitions.")
           Alchemy.t(:ingredient_definition_missing)
         else
           definition.deprecation_notice(element_name: element&.name)
diff --git a/app/controllers/alchemy/admin/base_controller.rb b/app/controllers/alchemy/admin/base_controller.rb
@@ -167,7 +167,7 @@ def notify_error_tracker(exception)
         if ::Alchemy::ErrorTracking.notification_handler.respond_to?(:call)
           ::Alchemy::ErrorTracking.notification_handler.call(exception)
         else
-          Rails.logger.warn("To use the Alchemy::ErrorTracking.notification_handler, it must respond to #call.")
+          Logger.warn("To use the Alchemy::ErrorTracking.notification_handler, it must respond to #call.")
         end
       end
     end
diff --git a/app/controllers/alchemy/base_controller.rb b/app/controllers/alchemy/base_controller.rb
@@ -48,7 +48,7 @@ def mailer_set_url_options
 
     def permission_denied(exception = nil)
       if exception
-        Rails.logger.debug <<-WARN.strip_heredoc
+        Logger.debug <<-WARN.strip_heredoc
           /!\\ Failed to permit #{exception.action} on #{exception.subject.inspect} for:
           #{current_alchemy_user.inspect}
         WARN
@@ -101,8 +101,8 @@ def handle_redirect_for_guest
 
     # Logs the current exception to the error log.
     def exception_logger(error)
-      Rails.logger.error("\n#{error.class} #{error.message} in #{error.backtrace.first}")
-      Rails.logger.error(error.backtrace[1..50].each { |line|
+      Logger.error("\n#{error.class} #{error.message} in #{error.backtrace.first}")
+      Logger.error(error.backtrace[1..50].each { |line|
         line.gsub(/#{Rails.root}/, "")
       }.join("\n"))
     end
diff --git a/app/decorators/alchemy/ingredient_editor.rb b/app/decorators/alchemy/ingredient_editor.rb
@@ -112,7 +112,7 @@ def warnings
       return unless has_warnings?
 
       if definition.blank?
-        Logger.warn("ingredient #{role} is missing its definition", caller(1..1))
+        Logger.warn("ingredient '#{role}' is missing its definition! Please check your element definitions.")
         Alchemy.t(:ingredient_definition_missing)
       else
         definition.deprecation_notice(element_name: element&.name)
diff --git a/app/helpers/alchemy/base_helper.rb b/app/helpers/alchemy/base_helper.rb
@@ -5,7 +5,7 @@ module BaseHelper
     # Logs a message in the Rails logger (warn level)
     # and optionally displays an error message to the user.
     def warning(message, text = nil)
-      Logger.warn(message, caller(1..1))
+      Logger.warn(message)
       unless text.nil?
         render_message(:warning) do
           text.html_safe
diff --git a/app/helpers/alchemy/pages_helper.rb b/app/helpers/alchemy/pages_helper.rb
@@ -172,7 +172,7 @@ def error_or_warning(error, message)
       if Rails.application.config.consider_all_requests_local?
         raise error, message
       else
-        Rails.logger.error message
+        Logger.error message
         ""
       end
     end
diff --git a/app/models/alchemy/element.rb b/app/models/alchemy/element.rb
@@ -28,7 +28,6 @@ module Alchemy
   class Element < BaseRecord
     NAME_REGEXP = /\A[a-z0-9_-]+\z/
 
-    include Alchemy::Logger
     include Alchemy::Taggable
 
     FORBIDDEN_DEFINITION_ATTRIBUTES = [
@@ -287,7 +286,7 @@ def generate_nested_elements
         if nestable_elements.include?(nestable_element)
           Element.create(page_version: page_version, parent_element_id: id, name: nestable_element)
         else
-          log_warning("Element '#{nestable_element}' not a nestable element for '#{name}'. Skipping!")
+          Logger.warn("Element '#{nestable_element}' not a nestable element for '#{name}'. Skipping!")
         end
       end
     end
diff --git a/app/models/alchemy/element/definitions.rb b/app/models/alchemy/element/definitions.rb
@@ -44,8 +44,7 @@ def definition
         if (definition = self.class.definition_by_name(name))
           definition
         else
-          log_warning "Could not find element definition for #{name}. " \
-                      "Please check your elements.yml file!"
+          Logger.warn "Could not find element definition for '#{name}'! Please check your element definitions."
           ElementDefinition.new
         end
       end
diff --git a/app/models/alchemy/element/element_ingredients.rb b/app/models/alchemy/element/element_ingredients.rb
@@ -61,8 +61,12 @@ def ingredient_definition_for(role)
         if ingredient_definitions.blank?
           nil
         else
-          ingredient_definitions.find { _1.role == role.to_s } ||
-            log_warning("Element #{name} is missing the ingredient definition for #{role}")
+          definition = ingredient_definitions.find { _1.role == role.to_s }
+          return definition if definition.present?
+
+          Logger.warn <<-WARN.strip_heredoc
+            Element '#{name}' is missing the ingredient definition for '#{role}'! Please check your element definitions.
+          WARN
         end
       end
 
diff --git a/app/models/alchemy/page.rb b/app/models/alchemy/page.rb
@@ -44,7 +44,6 @@
 
 module Alchemy
   class Page < BaseRecord
-    include Alchemy::Logger
     include Alchemy::Taggable
 
     DEFAULT_ATTRIBUTES_FOR_COPY = {
diff --git a/app/models/alchemy/page/page_natures.rb b/app/models/alchemy/page/page_natures.rb
@@ -99,7 +99,7 @@ def status_title(status_type)
       def definition
         definition = PageDefinition.get(page_layout)
         if definition.nil?
-          log_warning "Page definition for `#{page_layout}` not found. Please check `page_layouts.yml` file."
+          Logger.warn "Page definition for '#{page_layout}' not found. Please check page_layouts.yml file."
           return PageDefinition.new
         end
         definition
diff --git a/app/models/alchemy/picture.rb b/app/models/alchemy/picture.rb
@@ -28,7 +28,6 @@ class Picture < BaseRecord
       large: "240x180"
     }.with_indifferent_access.freeze
 
-    include Alchemy::Logger
     include Alchemy::NameConversions
     include Alchemy::Taggable
     include Alchemy::TouchElements
@@ -148,7 +147,7 @@ def url(options = {})
 
       self.class.url_class.new(self).call(options)
     rescue Alchemy.storage_adapter.rescuable_errors => e
-      log_warning(e.message)
+      Logger.warn(e.message)
       nil
     end
 
diff --git a/app/models/alchemy/picture_variant.rb b/app/models/alchemy/picture_variant.rb
@@ -10,8 +10,6 @@ module Alchemy
   class PictureVariant
     extend Forwardable
 
-    include Alchemy::Logger
-
     ANIMATED_IMAGE_FORMATS = %w[gif webp]
     TRANSPARENT_IMAGE_FORMATS = %w[gif webp png]
     ENCODABLE_IMAGE_FORMATS = %w[jpg jpeg webp]
@@ -57,7 +55,7 @@ def image
       image = processed_image(image, @options)
       encoded_image(image, @options)
     rescue MissingImageFileError, WrongImageFormatError => e
-      log_warning(e.message)
+      Logger.warn(e.message)
       nil
     end
 
diff --git a/config/locales/alchemy.en.yml b/config/locales/alchemy.en.yml
@@ -359,9 +359,9 @@ en:
     "Visit page": "Visit page"
     "Warning!": "Warning!"
     ingredient_deprecated: "WARNING! This field is deprecated and will be removed soon. Please do not use it anymore."
-    element_definition_missing: "WARNING! Missing element definition. Please check your elements.yml file."
+    element_definition_missing: "WARNING: Missing element definition! Please check your element definitions."
     element_deprecated: "WARNING! This element is deprecated and will be removed soon. Please do not use it anymore."
-    page_definition_missing: "WARNING! Missing page layout definition. Please check your page_layouts.yml file."
+    page_definition_missing: "WARNING: Missing page layout definition! Please check your page definitions."
     "Welcome to Alchemy": "Welcome to Alchemy"
     "Who else is online": "Who else is online"
     "Yes": "Yes"
diff --git a/lib/alchemy/auth_accessors.rb b/lib/alchemy/auth_accessors.rb
@@ -96,7 +96,7 @@ def self.user_class
       @@user_class_name.constantize
     rescue NameError => e
       if /#{Regexp.escape(@@user_class_name)}/.match?(e.message)
-        Rails.logger.warn <<~MSG
+        Logger.warn <<~MSG
           #{e.message}
           #{e.backtrace.join("\n")}
 
diff --git a/lib/alchemy/engine.rb b/lib/alchemy/engine.rb
@@ -79,11 +79,11 @@ class Engine < Rails::Engine
     config.to_prepare do
       # Definition files
       elements_reloader = Rails.application.config.file_watcher.new([ElementDefinition.definitions_file_path]) do
-        Rails.logger.info "[alchemy] Reloading Element Definitions."
+        Logger.info "Reloading Element Definitions."
         ElementDefinition.reset!
       end
       page_layouts_reloader = Rails.application.config.file_watcher.new([PageDefinition.layouts_file_path]) do
-        Rails.logger.info "[alchemy] Reloading Page Layouts."
+        Logger.info "Reloading Page Layouts."
         PageDefinition.reset!
       end
       [elements_reloader, page_layouts_reloader].each do |reloader|
diff --git a/lib/alchemy/error_tracking/error_logger.rb b/lib/alchemy/error_tracking/error_logger.rb
@@ -4,7 +4,7 @@ module Alchemy
   module ErrorTracking
     class ErrorLogger < BaseHandler
       def self.call(exception)
-        ::Rails.logger.tagged("alchemy_cms") do
+        ::Rails.logger.tagged("alchemy") do
           ::Rails.logger.error("#{exception.class.name}: #{exception.message} in #{exception.backtrace.first}")
         end
       end
diff --git a/lib/alchemy/errors.rb b/lib/alchemy/errors.rb
@@ -26,7 +26,7 @@ def initialize(attributes)
     end
 
     def message
-      "Element definition for #{@name} not found. Please check your elements.yml"
+      "Element definition for '#{@name}' not found! Please check your element definitions."
     end
   end
 
diff --git a/lib/alchemy/logger.rb b/lib/alchemy/logger.rb
@@ -2,14 +2,44 @@
 
 module Alchemy
   module Logger
-    # Logs a debug message to the Rails standard logger and adds some nicer formatting
-    def self.warn(message, caller_string)
-      Rails.logger.debug %(\n++++ WARNING: #{message}\nCalled from: #{caller_string}\n)
+    # Logs a debug message to the Rails standard logger
+    def self.debug(message)
+      Rails.logger.tagged("alchemy") do
+        Rails.logger.debug(message)
+      end
+      nil
+    end
+
+    # Logs a error message to the Rails standard logger
+    def self.error(message)
+      Rails.logger.tagged("alchemy") do
+        Rails.logger.error("ERROR: #{message}")
+      end
+      nil
+    end
+
+    # Logs a info message to the Rails standard logger
+    def self.info(message)
+      Rails.logger.tagged("alchemy") do
+        Rails.logger.info(message)
+      end
+      nil
+    end
+
+    # Logs a warning message to the Rails standard logger
+    def self.warn(message, caller_string = nil)
+      if caller_string
+        Alchemy::Deprecation.warn("Alchemy::Logger.warn second argument is deprecated and will be removed in Alchemy 9.0")
+      end
+      Rails.logger.tagged("alchemy") do
+        Rails.logger.warn("WARNING: #{message}")
+      end
       nil
     end
 
     def log_warning(message)
-      Alchemy::Logger.warn(message, caller(1..1))
+      Alchemy::Logger.warn(message)
     end
+    deprecate log_warning: "Alchemy::Logger.warn", deprecator: Alchemy::Deprecation
   end
 end
diff --git a/spec/libraries/alchemy/error_tracking/error_logger_spec.rb b/spec/libraries/alchemy/error_tracking/error_logger_spec.rb
@@ -5,7 +5,7 @@
 RSpec.describe Alchemy::ErrorTracking::ErrorLogger do
   describe ".call" do
     it "logs the exception into Rails logger with alchemy_cms tag" do
-      expect(::Rails.logger).to receive(:tagged).with("alchemy_cms").and_yield
+      expect(::Rails.logger).to receive(:tagged).with("alchemy").and_yield
       expect(::Rails.logger).to receive(:error).with("RuntimeError: foo in /foo/bar.rb:1")
       error = RuntimeError.new("foo")
       error.set_backtrace(["/foo/bar.rb:1"])
diff --git a/spec/libraries/logger_spec.rb b/spec/libraries/logger_spec.rb
@@ -9,28 +9,86 @@ class Something
 RSpec.describe Alchemy::Logger do
   let(:message) { "Something bad happened" }
 
+  describe ".debug" do
+    subject { described_class.debug(message) }
+
+    it { is_expected.to be_nil }
+
+    it "uses Rails debug logger" do
+      expect(Rails.logger).to receive(:debug).with(message)
+      subject
+    end
+
+    it "adds a Rails log tag" do
+      expect(Rails.logger).to receive(:tagged).with("alchemy").and_yield
+      subject
+    end
+  end
+
+  describe ".error" do
+    subject { described_class.error(message) }
+
+    it { is_expected.to be_nil }
+
+    it "uses Rails error logger" do
+      expect(Rails.logger).to receive(:error).with("ERROR: #{message}")
+      subject
+    end
+
+    it "adds a Rails log tag" do
+      expect(Rails.logger).to receive(:tagged).with("alchemy").and_yield
+      subject
+    end
+  end
+
+  describe ".info" do
+    subject { described_class.info(message) }
+
+    it { is_expected.to be_nil }
+
+    it "uses Rails info logger" do
+      expect(Rails.logger).to receive(:info).with(message)
+      subject
+    end
+
+    it "adds a Rails log tag" do
+      expect(Rails.logger).to receive(:tagged).with("alchemy").and_yield
+      subject
+    end
+  end
+
   describe ".warn" do
-    let(:caller_string) { "file.rb:14" }
+    subject { Alchemy::Logger.warn(message) }
+
+    context "when called with caller_string" do
+      let(:caller_string) { "file.rb:14" }
 
-    subject { Alchemy::Logger.warn(message, caller_string) }
+      subject { Alchemy::Logger.warn(message, caller_string) }
+
+      it "logs a deprecation warning about the second argument" do
+        expect(Alchemy::Deprecation).to receive(:warn).with(/second argument is deprecated/)
+        subject
+      end
+    end
 
     it { is_expected.to be_nil }
 
-    it "uses Rails debug logger" do
-      expect(Rails.logger).to receive(:debug) { message }
+    it "uses Rails warn logger" do
+      expect(Rails.logger).to receive(:warn).with("WARNING: #{message}")
+      subject
+    end
+
+    it "adds a Rails log tag" do
+      expect(Rails.logger).to receive(:tagged).with("alchemy").and_yield
       subject
     end
   end
 
   describe "#log_warning" do
     subject { Something.new.log_warning(message) }
 
-    before do
-      expect_any_instance_of(Something).to receive(:caller).with(1..1) { ["second"] }
-    end
-
-    it "delegates to Alchemy::Logger.warn class method with second line of callstack" do
-      expect(Alchemy::Logger).to receive(:warn).with(message, ["second"])
+    it "delegates to Alchemy::Logger.warn class method with second line of callstack", :silence_deprecations do
+      expect(Alchemy::Logger).to receive(:warn).with(message)
       subject
     end
   end
diff --git a/spec/models/alchemy/element_spec.rb b/spec/models/alchemy/element_spec.rb
@@ -92,8 +92,8 @@ module Alchemy
           end
 
           it "logs error warning" do
-            expect_any_instance_of(Alchemy::Logger).to \
-              receive(:log_warning).with("Element 'bar' not a nestable element for 'slider'. Skipping!")
+            expect(Alchemy::Logger).to \
+              receive(:warn).with("Element 'bar' not a nestable element for 'slider'. Skipping!")
             element
           end
 
