test/logger_test.rb in semantic_logger-3.0.1 vs test/logger_test.rb in semantic_logger-3.1.0

@@ -1,26 +1,125 @@
 require_relative 'test_helper'
 
 # Unit Test for SemanticLogger::Logger
 class LoggerTest < Minitest::Test
   describe SemanticLogger::Logger do
+    describe '.add_appender' do
+      after do
+        SemanticLogger.remove_appender(@appender) if @appender
+        File.delete('sample.log') if File.exists?('sample.log')
+      end
+
+      it 'adds file appender' do
+        @appender = SemanticLogger.add_appender(file_name: 'sample.log')
+        assert @appender.is_a?(SemanticLogger::Appender::File)
+        assert SemanticLogger.appenders.include?(@appender)
+        assert @appender.formatter.is_a?(SemanticLogger::Formatters::Default)
+      end
+
+      it 'adds file appender with json format' do
+        @appender = SemanticLogger.add_appender(file_name: 'sample.log', formatter: :json)
+        assert @appender.is_a?(SemanticLogger::Appender::File)
+        assert SemanticLogger.appenders.include?(@appender)
+        assert @appender.formatter.is_a?(SemanticLogger::Formatters::Json)
+      end
+
+      it 'adds stream appender' do
+        @appender = SemanticLogger.add_appender(io: STDOUT)
+        assert @appender.is_a?(SemanticLogger::Appender::File)
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'adds symbol appender' do
+        @appender = SemanticLogger.add_appender(appender: :http, url: 'http://localhost:8088/path')
+        assert @appender.is_a?(SemanticLogger::Appender::Http), @appender.ai
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'adds logger wrapper appender' do
+        @appender = SemanticLogger.add_appender(logger: ::Logger.new(STDOUT))
+        assert @appender.is_a?(SemanticLogger::Appender::Wrapper)
+        assert @appender.logger.is_a?(::Logger)
+        assert SemanticLogger.appenders.include?(@appender)
+        assert @appender.formatter.is_a?(SemanticLogger::Formatters::Default)
+      end
+
+      it 'adds logger wrapper appender with color formatter' do
+        @appender = SemanticLogger.add_appender(logger: ::Logger.new(STDOUT), formatter: :color)
+        assert @appender.is_a?(SemanticLogger::Appender::Wrapper)
+        assert @appender.logger.is_a?(::Logger)
+        assert SemanticLogger.appenders.include?(@appender)
+        assert @appender.formatter.is_a?(SemanticLogger::Formatters::Color)
+      end
+
+      it 'adds appender' do
+        @appender = SemanticLogger.add_appender(appender: SemanticLogger::Appender::Http.new(url: 'http://localhost:8088/path'))
+        assert @appender.is_a?(SemanticLogger::Appender::Http), @appender.ai
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'fails to add invalid logger appender' do
+        assert_raises do
+          SemanticLogger.add_appender(logger: 'blah')
+        end
+      end
+    end
+
+    describe '.add_appender DEPRECATED' do
+      after do
+        SemanticLogger.remove_appender(@appender) if @appender
+        File.delete('sample.log') if File.exists?('sample.log')
+      end
+
+      it 'adds file appender' do
+        @appender = SemanticLogger.add_appender('sample.log')
+        assert @appender.is_a?(SemanticLogger::Appender::File)
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'adds stream appender' do
+        @appender = SemanticLogger.add_appender(STDOUT)
+        assert @appender.is_a?(SemanticLogger::Appender::File)
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'adds appender' do
+        @appender = SemanticLogger.add_appender(SemanticLogger::Appender::Http.new(url: 'http://localhost:8088/path'))
+        assert @appender.is_a?(SemanticLogger::Appender::Http), @appender.ai
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'adds logger wrapper appender' do
+        @appender = SemanticLogger.add_appender(::Logger.new(STDOUT))
+        assert @appender.is_a?(SemanticLogger::Appender::Wrapper)
+        assert @appender.logger.is_a?(::Logger)
+        assert SemanticLogger.appenders.include?(@appender)
+      end
+
+      it 'fails to add invalid logger appender' do
+        assert_raises do
+          SemanticLogger.add_appender(logger: 'blah')
+        end
+      end
+    end
+
     # Test each filter
     [nil, /\ALogger/, Proc.new { |l| (/\AExclude/ =~ l.message).nil? }].each do |filter|
       describe "filter: #{filter.class.name}" do
         before do
           # Use a mock logger that just keeps the last logged entry in an instance
           # variable
           SemanticLogger.default_level   = :trace
           SemanticLogger.backtrace_level = nil
           @mock_logger                   = MockLogger.new
-          @appender                      = SemanticLogger.add_appender(@mock_logger)
+          @appender                      = SemanticLogger.add_appender(logger: @mock_logger)
           @appender.filter               = filter
 
           # Add mock metric subscriber
           $last_metric                   = nil
-          SemanticLogger.on_metric do |log_struct|
-            $last_metric = log_struct.dup
+          SemanticLogger.on_metric do |log|
+            $last_metric = log.dup
           end
 
           # Use this test's class name as the application name in the log output
           @logger            = SemanticLogger[LoggerTest]
           @hash              = {session_id: 'HSSKLEU@JDK767', tracking_number: 12345}
@@ -94,10 +193,70 @@
               @logger.send(level, 'Hello world', hash)
               SemanticLogger.flush
               assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] LoggerTest -- Hello world/, @mock_logger.message
             end
 
+            describe 'hash only argument' do
+              it 'logs message' do
+                @logger.send(level, message: 'Hello world')
+                SemanticLogger.flush
+                assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] LoggerTest -- Hello world/, @mock_logger.message
+              end
+
+              it 'logs payload and message' do
+                @logger.send(level, message: 'Hello world', tracking_number: '123456', even: 2, more: 'data')
+                hash = {tracking_number: '123456', even: 2, more: 'data'}
+                SemanticLogger.flush
+                hash_str = hash.inspect.sub('{', '\{').sub('}', '\}')
+                assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] LoggerTest -- Hello world -- #{hash_str}/, @mock_logger.message
+              end
+
+              it 'logs payload and message from block' do
+                @logger.send(level) { {message: 'Hello world', tracking_number: '123456', even: 2, more: 'data'} }
+                hash = {tracking_number: '123456', even: 2, more: 'data'}
+                SemanticLogger.flush
+                hash_str = hash.inspect.sub('{', '\{').sub('}', '\}')
+                assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] LoggerTest -- Hello world -- #{hash_str}/, @mock_logger.message
+              end
+
+              it 'logs payload only' do
+                hash = {tracking_number: '123456', even: 2, more: 'data'}
+                @logger.send(level, hash)
+                SemanticLogger.flush
+                hash_str = hash.inspect.sub('{', '\{').sub('}', '\}')
+                assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] LoggerTest -- #{hash_str}/, @mock_logger.message
+              end
+
+              it 'logs duration' do
+                @logger.send(level, duration: 123.45, message: 'Hello world', tracking_number: '123456', even: 2, more: 'data')
+                hash = {tracking_number: '123456', even: 2, more: 'data'}
+                SemanticLogger.flush
+                hash_str       = hash.inspect.sub('{', '\{').sub('}', '\}')
+                duration_match = defined?(JRuby) ? '\(123ms\)' : '\(123\.5ms\)'
+                assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] #{duration_match} LoggerTest -- Hello world -- #{hash_str}/, @mock_logger.message
+              end
+
+              it 'does not log when below min_duration' do
+                @logger.send(level, min_duration: 200, duration: 123.45, message: 'Hello world', tracking_number: '123456', even: 2, more: 'data')
+                hash = {tracking_number: '123456', even: 2, more: 'data'}
+                SemanticLogger.flush
+                assert_nil @mock_logger.message
+              end
+
+              it 'logs metric' do
+                metric_name = '/my/custom/metric'
+                @logger.send(level, metric: metric_name, duration: 123.45, message: 'Hello world', tracking_number: '123456', even: 2, more: 'data')
+                hash = {tracking_number: '123456', even: 2, more: 'data'}
+                SemanticLogger.flush
+                hash_str       = hash.inspect.sub('{', '\{').sub('}', '\}')
+                duration_match = defined?(JRuby) ? '\(123ms\)' : '\(123\.5ms\)'
+                assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] #{duration_match} LoggerTest -- Hello world -- #{hash_str}/, @mock_logger.message
+                assert metric_name, $last_metric.metric
+              end
+
+            end
+
           end
         end
 
         describe '#tagged' do
           it 'add tags to log entries' do
@@ -158,117 +317,117 @@
               end
             end
           end
         end
 
-        describe 'benchmark' do
-          # Ensure that any log level can be benchmarked and logged
+        describe 'measure' do
+          # Ensure that any log level can be measured and logged
           SemanticLogger::LEVELS.each do |level|
             level_char = level.to_s.upcase[0]
 
             describe 'direct method' do
               it "log #{level} info" do
-                assert_equal 'result', @logger.send("benchmark_#{level}".to_sym, 'hello world') { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.send("measure_#{level}".to_sym, 'hello world') { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
               end
 
               it "log #{level} info with payload" do
-                assert_equal 'result', @logger.send("benchmark_#{level}".to_sym, 'hello world', payload: @hash) { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.send("measure_#{level}".to_sym, 'hello world', payload: @hash) { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- #{@hash_str}/, @mock_logger.message
               end
 
               it "not log #{level} info when block is faster than :min_duration" do
-                assert_equal 'result', @logger.send("benchmark_#{level}".to_sym, 'hello world', min_duration: 500) { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.send("measure_#{level}".to_sym, 'hello world', min_duration: 500) { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_nil @mock_logger.message
               end
 
               it "log #{level} info when block duration exceeds :min_duration" do
-                assert_equal 'result', @logger.send("benchmark_#{level}".to_sym, 'hello world', min_duration: 200, payload: @hash) { sleep 0.5; 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.send("measure_#{level}".to_sym, 'hello world', min_duration: 200, payload: @hash) { sleep 0.5; 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- #{@hash_str}/, @mock_logger.message
               end
 
               it "log #{level} info with an exception" do
                 assert_raises RuntimeError do
-                  @logger.send("benchmark_#{level}", 'hello world', payload: @hash) { raise RuntimeError.new("Test") } # Measure duration of the supplied block
+                  @logger.send("measure_#{level}", 'hello world', payload: @hash) { raise RuntimeError.new("Test") } # Measure duration of the supplied block
                 end
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}#{@file_name_reg_exp}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- Exception: RuntimeError: Test -- #{@hash_str}/, @mock_logger.message
               end
 
               it "change log #{level} info with an exception" do
                 assert_raises RuntimeError do
-                  @logger.send("benchmark_#{level}", 'hello world', payload: @hash, on_exception_level: :fatal) { raise RuntimeError.new("Test") } # Measure duration of the supplied block
+                  @logger.send("measure_#{level}", 'hello world', payload: @hash, on_exception_level: :fatal) { raise RuntimeError.new("Test") } # Measure duration of the supplied block
                 end
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ F \[\d+:#{@thread_name}#{@file_name_reg_exp}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- Exception: RuntimeError: Test -- #{@hash_str}/, @mock_logger.message
               end
 
               it "log #{level} info with metric" do
                 metric_name = '/my/custom/metric'
-                assert_equal 'result', @logger.send("benchmark_#{level}".to_sym, 'hello world', metric: metric_name) { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.send("measure_#{level}".to_sym, 'hello world', metric: metric_name) { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
                 assert metric_name, $last_metric.metric
               end
 
               it "log #{level} info with backtrace" do
                 SemanticLogger.stub(:backtrace_level_index, 0) do
-                  assert_equal 'result', @logger.send("benchmark_#{level}".to_sym, 'hello world') { 'result' }
+                  assert_equal 'result', @logger.send("measure_#{level}".to_sym, 'hello world') { 'result' }
                   SemanticLogger.flush
                   assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}#{@file_name_reg_exp}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
                 end
               end
             end
 
             describe 'generic method' do
               it "log #{level} info" do
-                assert_equal 'result', @logger.benchmark(level, 'hello world') { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.measure(level, 'hello world') { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
               end
 
               it "log #{level} info with payload" do
-                assert_equal 'result', @logger.benchmark(level, 'hello world', payload: @hash) { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.measure(level, 'hello world', payload: @hash) { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- #{@hash_str}/, @mock_logger.message
               end
 
               it "not log #{level} info when block is faster than :min_duration" do
-                assert_equal 'result', @logger.benchmark(level, 'hello world', min_duration: 500) { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.measure(level, 'hello world', min_duration: 500) { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_nil @mock_logger.message
               end
 
               it "log #{level} info when block duration exceeds :min_duration" do
-                assert_equal 'result', @logger.benchmark(level, 'hello world', min_duration: 200, payload: @hash) { sleep 0.5; 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.measure(level, 'hello world', min_duration: 200, payload: @hash) { sleep 0.5; 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- #{@hash_str}/, @mock_logger.message
               end
 
               it "log #{level} info with an exception" do
                 assert_raises RuntimeError do
-                  @logger.benchmark(level, 'hello world', payload: @hash) { raise RuntimeError.new('Test') } # Measure duration of the supplied block
+                  @logger.measure(level, 'hello world', payload: @hash) { raise RuntimeError.new('Test') } # Measure duration of the supplied block
                 end
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}#{@file_name_reg_exp}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- Exception: RuntimeError: Test -- #{@hash_str}/, @mock_logger.message
               end
 
               it "log #{level} info with metric" do
                 metric_name = '/my/custom/metric'
-                assert_equal 'result', @logger.benchmark(level, 'hello world', metric: metric_name) { 'result' } # Measure duration of the supplied block
+                assert_equal 'result', @logger.measure(level, 'hello world', metric: metric_name) { 'result' } # Measure duration of the supplied block
                 SemanticLogger.flush
                 assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
                 assert metric_name, $last_metric.metric
               end
 
               it "log #{level} info with backtrace" do
                 SemanticLogger.stub(:backtrace_level_index, 0) do
-                  assert_equal 'result', @logger.benchmark(level, 'hello world') { 'result' }
+                  assert_equal 'result', @logger.measure(level, 'hello world') { 'result' }
                   SemanticLogger.flush
                   assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}#{@file_name_reg_exp}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
                 end
               end
             end
@@ -280,21 +439,21 @@
             assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ I \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world -- #{@hash_str}/, @mock_logger.message
           end
 
           it 'not log at a level below the silence level' do
             SemanticLogger.default_level = :info
-            @logger.benchmark_info('hello world', silence: :error) do
+            @logger.measure_info('hello world', silence: :error) do
               @logger.warn "don't log me"
             end
             SemanticLogger.flush
             assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ I \[\d+:#{@thread_name}\] \((\d+\.\d+)|(\d+)ms\) LoggerTest -- hello world/, @mock_logger.message
           end
 
           it 'log at a silence level below the default level' do
             SemanticLogger.default_level = :info
             first_message                = nil
-            @logger.benchmark_info('hello world', silence: :trace) do
+            @logger.measure_info('hello world', silence: :trace) do
               @logger.debug('hello world', @hash) { 'Calculations' }
               SemanticLogger.flush
               first_message = @mock_logger.message
             end
             assert_match /\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{@thread_name}\] LoggerTest -- hello world -- Calculations -- #{@hash_str}/, first_message
@@ -413,13 +572,13 @@
         end
 
       end
     end
 
-    # Make sure that benchmark still logs when a block uses return to return from
+    # Make sure that measure still logs when a block uses return to return from
     # a function
     def function_with_return(logger)
-      logger.benchmark_info('hello world', payload: @hash) do
+      logger.measure_info('hello world', payload: @hash) do
         return 'Good'
       end
       'Bad'
     end