From ad83dd6e89fd3ad0c5f1491910e4bd9f8d0641c4 Mon Sep 17 00:00:00 2001 From: Tom de Bruijn Date: Wed, 4 Dec 2024 17:02:31 +0100 Subject: [PATCH 1/2] Don't use thread vars in logger To temporarily set the attributes in the logger instance, use instance variables instead of Thread variables. I don't know why Thread variables are used here. I don't think it's needed. --- lib/appsignal/logger.rb | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/lib/appsignal/logger.rb b/lib/appsignal/logger.rb index a0dc2fb4..6cc9a3c5 100644 --- a/lib/appsignal/logger.rb +++ b/lib/appsignal/logger.rb @@ -37,6 +37,7 @@ def initialize(group, level: INFO, format: PLAINTEXT, attributes: {}) @format = format @mutex = Mutex.new @default_attributes = attributes + @appsignal_attributes = {} end # We support the various methods in the Ruby @@ -159,17 +160,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 From 41e1e8f076025da2420cb43c53b5f7211ae45de8 Mon Sep 17 00:00:00 2001 From: Tom de Bruijn Date: Thu, 5 Dec 2024 10:16:37 +0100 Subject: [PATCH 2/2] Add ActiveSupport tagged logging support Our logger did not support Rails ActiveSupport tagged logging yet. This was because our logger didn't listen to the `tagged`, `push_tags` and `pop_tags` methods. Implement these methods to have the logger that wraps our logger call these methods to set tags. The format is the same as Rails formats it: `[My tag value]` I decide not to set these as attributes, because they're only values. They have no key and the value can be anything and change frequently. --- .../add-rails-activesupport-tagged-logging.md | 14 +++ lib/appsignal/logger.rb | 29 +++++ spec/lib/appsignal/logger_spec.rb | 114 ++++++++++++++++++ 3 files changed, 157 insertions(+) create mode 100644 .changesets/add-rails-activesupport-tagged-logging.md diff --git a/.changesets/add-rails-activesupport-tagged-logging.md b/.changesets/add-rails-activesupport-tagged-logging.md new file mode 100644 index 00000000..97e950ea --- /dev/null +++ b/.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 diff --git a/lib/appsignal/logger.rb b/lib/appsignal/logger.rb index 6cc9a3c5..79dff48e 100644 --- a/lib/appsignal/logger.rb +++ b/lib/appsignal/logger.rb @@ -38,6 +38,7 @@ def initialize(group, level: INFO, format: PLAINTEXT, attributes: {}) @mutex = Mutex.new @default_attributes = attributes @appsignal_attributes = {} + @tags = [] end # We support the various methods in the Ruby @@ -58,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) @@ -144,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 diff --git a/spec/lib/appsignal/logger_spec.rb b/spec/lib/appsignal/logger_spec.rb index 56af7bdb..4d5206ed 100644 --- a/spec/lib/appsignal/logger_spec.rb +++ b/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