Use log_level option in Ruby logger (#780)

We've added the log_level option in PR #773. This primarily configured
it for the extension and agent, but not the integration's logger itself.

Add a `Appsignal::Config#log_level` helper method to figure out what log
level to set based on deprecated options and the new log_level option.
This mimics the extension and agent's behaviors. It relies on the
extension's output being printed to STDERR for (deprecation) warnings
about the configuration, so no warnings are printed by the Ruby gem
itself.

I've removed the default config of `log_level: info` so that debug and
transaction_debug_mode can still overwrite that level in the Ruby gem.
This is the same behavior as the extension and agent.

.changesets/use-log_level-option-for-ruby-gem-logger.md

@@ -0,0 +1,6 @@
+---
+bump: "patch"
+type: "fix"
+---
+
+Use the `log_level` option for the Ruby gem logger. Previously it only configured the extension and agent loggers. Also fixes the `debug` and `transaction_debug_mode` option if no `log_level` is configured by the app.

lib/appsignal.rb

@@ -116,12 +116,7 @@ def start
       )
 
       if config.valid?
-        logger.level =
-          if config[:debug]
-            Logger::DEBUG
-          else
-            Logger::INFO
-          end
+        logger.level = config.log_level
         if config.active?
           logger.info "Starting AppSignal #{Appsignal::VERSION} "\
             "(#{$PROGRAM_NAME}, Ruby #{RUBY_VERSION}, #{RUBY_PLATFORM})"
@@ -230,12 +225,11 @@ def start_logger
       end
 
       logger.level =
-        if config && config[:debug]
-          Logger::DEBUG
+        if config
+          config.log_level
         else
-          Logger::INFO
+          Appsignal::Config::DEFAULT_LOG_LEVEL
         end
-
       logger << @in_memory_log.string if @in_memory_log
     end
 

lib/appsignal/config.rb

@@ -30,7 +30,6 @@ class Config
       :instrument_redis               => true,
       :instrument_sequel              => true,
       :log                            => "file",
-      :log_level                      => "info",
       :request_headers                => %w[
         HTTP_ACCEPT HTTP_ACCEPT_CHARSET HTTP_ACCEPT_ENCODING
         HTTP_ACCEPT_LANGUAGE HTTP_CACHE_CONTROL HTTP_CONNECTION
@@ -44,6 +43,20 @@ class Config
       :transaction_debug_mode         => false
     }.freeze
 
+    # @api private
+    DEFAULT_LOG_LEVEL = Logger::INFO
+    # Map from the `log_level` config option to Ruby's Logger level value.
+    #
+    # The trace level doesn't exist in the Ruby logger so it's mapped to debug.
+    # @api private
+    LOG_LEVEL_MAP = {
+      "error" => Logger::ERROR,
+      "warn" => Logger::WARN,
+      "info" => Logger::INFO,
+      "debug" => Logger::DEBUG,
+      "trace" => Logger::DEBUG
+    }.freeze
+
     ENV_TO_KEY_MAPPING = {
       "APPSIGNAL_ACTIVE"                         => :active,
       "APPSIGNAL_APP_NAME"                       => :name,
@@ -242,6 +255,18 @@ def []=(key, value)
       config_hash[key] = value
     end
 
+    def log_level
+      if config_hash[:debug] || config_hash[:transaction_debug_mode]
+        level = Logger::DEBUG
+      end
+      option = config_hash[:log_level]
+      if option
+        log_level_option = LOG_LEVEL_MAP[option]
+        level = log_level_option if log_level_option
+      end
+      level.nil? ? Appsignal::Config::DEFAULT_LOG_LEVEL : level
+    end
+
     def log_file_path
       path = config_hash[:log_path] || root_path && File.join(root_path, "log")
       if path && File.writable?(path)

spec/lib/appsignal/config_spec.rb

@@ -171,7 +171,6 @@
         :instrument_redis               => true,
         :instrument_sequel              => true,
         :log                            => "file",
-        :log_level                      => "info",
         :name                           => "TestApp",
         :push_api_key                   => "abc",
         :request_headers                => [],
@@ -787,4 +786,83 @@
       end
     end
   end
+
+  describe "#log_level" do
+    let(:options) { {} }
+    let(:config) { described_class.new("", nil, options) }
+    subject { config.log_level }
+
+    context "without any config" do
+      it "returns info by default" do
+        is_expected.to eq(Logger::INFO)
+      end
+    end
+
+    context "with debug set to true" do
+      let(:options) { { :debug => true } }
+      it { is_expected.to eq(Logger::DEBUG) }
+    end
+
+    context "with transaction_debug_mode set to true" do
+      let(:options) { { :transaction_debug_mode => true } }
+      it { is_expected.to eq(Logger::DEBUG) }
+    end
+
+    context "with log_level set to error" do
+      let(:options) { { :log_level => "error" } }
+      it { is_expected.to eq(Logger::ERROR) }
+    end
+
+    context "with log_level set to warn" do
+      let(:options) { { :log_level => "warn" } }
+      it { is_expected.to eq(Logger::WARN) }
+    end
+
+    context "with log_level set to info" do
+      let(:options) { { :log_level => "info" } }
+      it { is_expected.to eq(Logger::INFO) }
+    end
+
+    context "with log_level set to debug" do
+      let(:options) { { :log_level => "debug" } }
+      it { is_expected.to eq(Logger::DEBUG) }
+    end
+
+    context "with log_level set to trace" do
+      let(:options) { { :log_level => "trace" } }
+      it { is_expected.to eq(Logger::DEBUG) }
+    end
+
+    context "with debug and log_level set" do
+      let(:options) { { :log_level => "error", :debug => true } }
+
+      it "the log_level option is leading" do
+        is_expected.to eq(Logger::ERROR)
+      end
+    end
+
+    context "with transaction_debug_mode and log_level set" do
+      let(:options) { { :log_level => "error", :transaction_debug_mode => true } }
+
+      it "the log_level option is leading" do
+        is_expected.to eq(Logger::ERROR)
+      end
+    end
+
+    context "with log level set to an unknown value" do
+      let(:options) { { :log_level => "fatal" } }
+
+      it "prints a warning and doesn't use the log_level" do
+        is_expected.to eql(Logger::INFO)
+      end
+
+      context "with debug option set to true" do
+        let(:options) { { :log_level => "fatal", :debug => true } }
+
+        it "prints a warning and sets it to debug" do
+          is_expected.to eql(Logger::DEBUG)
+        end
+      end
+    end
+  end
 end

spec/lib/appsignal_spec.rb

@@ -1236,7 +1236,7 @@ def initialize_config
           before do
             capture_stdout(out_stream) do
               initialize_config
-              Appsignal.config[:debug] = true
+              Appsignal.config[:log_level] = "debug"
               Appsignal.start_logger
             end
           end