Merge pull request #1344 from appsignal/tagged-logging

Add ActiveSupport tagged logging support

.changesets/add-rails-activesupport-tagged-logging.md

@@ -0,0 +1,14 @@
+---
+bump: patch
+type: add
+---
+
+Support Rails/ActiveSupport tagged logging. When tags are set in apps using `Rails.logger.tagged { ... }` or with the `Rails.application.config.log_tags = [...]` config option, these tags are now included in the collected log messages.
+
+```ruby
+Rails.logger.tagged(["Tag 1", "Tag 2"]) { Rails.logger.info("My message") }
+```
+
+Reports this log message:
+
+> [Tag 1] [Tag 2] My message

lib/appsignal/logger.rb

@@ -37,6 +37,8 @@ def initialize(group, level: INFO, format: PLAINTEXT, attributes: {})
       @format = format
       @mutex = Mutex.new
       @default_attributes = attributes
+      @appsignal_attributes = {}
+      @tags = []
     end
 
     # We support the various methods in the Ruby
@@ -57,6 +59,11 @@ def add(severity, message = nil, group = nil)
       end
       return if message.nil?
 
+      if @tags.any?
+        formatted_tags = @tags.map { |tag| "[#{tag}]" }
+        message = "#{formatted_tags.join(" ")} #{message}"
+      end
+
       message = formatter.call(severity, Time.now, group, message) if formatter
 
       unless message.is_a?(String)
@@ -143,6 +150,29 @@ def fatal(message = nil, attributes = {})
       add_with_attributes(FATAL, message, @group, attributes)
     end
 
+    # Listen to ActiveSupport tagged logging tags set with `Rails.logger.tagged`.
+    def tagged(tags)
+      @tags.append(*tags)
+      yield self
+    ensure
+      @tags.pop(tags.length)
+    end
+
+    # Listen to ActiveSupport tagged logging tags set with `Rails.config.log_tags`.
+    def push_tags(tags)
+      @tags.append(*tags)
+    end
+
+    # Remove a set of ActiveSupport tagged logging tags set with `Rails.config.log_tags`.
+    def pop_tags(count = 1)
+      @tags.pop(count)
+    end
+
+    # Remove all ActiveSupport tagged logging tags set with `Rails.config.log_tags`.
+    def clear_tags!
+      @tags.clear
+    end
+
     # When using ActiveSupport::TaggedLogging without the broadcast feature,
     # the passed logger is required to respond to the `silence` method.
     # In our case it behaves as the broadcast feature of the Rails logger, but
@@ -159,17 +189,13 @@ def silence(_severity = ERROR, &block)
 
     private
 
-    attr_reader :default_attributes
+    attr_reader :default_attributes, :appsignal_attributes
 
     def add_with_attributes(severity, message, group, attributes)
-      Thread.current[:appsignal_logger_attributes] = default_attributes.merge(attributes)
+      @appsignal_attributes = default_attributes.merge(attributes)
       add(severity, message, group)
     ensure
-      Thread.current[:appsignal_logger_attributes] = nil
-    end
-
-    def appsignal_attributes
-      Thread.current.fetch(:appsignal_logger_attributes, {})
+      @appsignal_attributes = {}
     end
   end
 end

spec/lib/appsignal/logger_spec.rb

@@ -232,4 +232,118 @@
       logger.error(error)
     end
   end
+
+  if DependencyHelper.rails_present?
+    describe "tagged logging" do
+      it "logs messages with tags from logger.tagged" do
+        expect(Appsignal::Extension).to receive(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[My tag] [My other tag] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+
+        appsignal_logger = Appsignal::Logger.new("group")
+        logger = ActiveSupport::TaggedLogging.new(appsignal_logger)
+        logger.tagged("My tag", "My other tag") do
+          logger.info("Some message")
+        end
+      end
+
+      it "logs messages with nested tags from logger.tagged" do
+        expect(Appsignal::Extension).to receive(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[My tag] [My other tag] [Nested tag] [Nested other tag] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+
+        appsignal_logger = Appsignal::Logger.new("group")
+        logger = ActiveSupport::TaggedLogging.new(appsignal_logger)
+        logger.tagged("My tag", "My other tag") do
+          logger.tagged("Nested tag", "Nested other tag") do
+            logger.info("Some message")
+          end
+        end
+      end
+
+      it "logs messages with tags from Rails.application.config.log_tags" do
+        allow(Appsignal::Extension).to receive(:log)
+
+        appsignal_logger = Appsignal::Logger.new("group")
+        logger = ActiveSupport::TaggedLogging.new(appsignal_logger)
+
+        # This is how Rails sets the `log_tags` values
+        logger.push_tags(["Request tag", "Second tag"])
+        logger.tagged("First message", "My other tag") { logger.info("Some message") }
+        expect(Appsignal::Extension).to have_received(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[Request tag] [Second tag] [First message] [My other tag] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+
+        # Logs all messsages within the time between `push_tags` and `pop_tags`
+        # with the same set tags
+        logger.tagged("Second message") { logger.info("Some message") }
+        expect(Appsignal::Extension).to have_received(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[Request tag] [Second tag] [Second message] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+
+        # This is how Rails clears the `log_tags` values
+        # It will no longer includes those tags in new log messages
+        logger.pop_tags(2)
+        logger.tagged("Third message") { logger.info("Some message") }
+        expect(Appsignal::Extension).to have_received(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[Third message] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+      end
+
+      it "clears all tags with clear_tags!" do
+        allow(Appsignal::Extension).to receive(:log)
+
+        appsignal_logger = Appsignal::Logger.new("group")
+        logger = ActiveSupport::TaggedLogging.new(appsignal_logger)
+
+        # This is how Rails sets the `log_tags` values
+        logger.push_tags(["Request tag", "Second tag"])
+        logger.tagged("First message", "My other tag") { logger.info("Some message") }
+        expect(Appsignal::Extension).to have_received(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[Request tag] [Second tag] [First message] [My other tag] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+
+        logger.clear_tags!
+        logger.tagged("First message", "My other tag") { logger.info("Some message") }
+        expect(Appsignal::Extension).to have_received(:log)
+          .with(
+            "group",
+            3,
+            0,
+            "[First message] [My other tag] Some message\n",
+            Appsignal::Utils::Data.generate({})
+          )
+      end
+    end
+  end
 end