diff --git a/CHANGELOG.md b/CHANGELOG.md index d98755a5..d693bdcf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,10 +5,13 @@ This project adheres to [Semantic Versioning](http://semver.org/). ## [unreleased] -- Add support for Ruby 3.3 -- Allow SyncProcessor to be called from appenders -- Fix incorrect metrics usage examples in documentation -- Add `:duration_ms` to Logfmt fomatter +## [4.16.0] + +- Add support for Ruby 3.3. +- Allow SyncProcessor to be called from appenders. +- Fix incorrect metrics usage examples in documentation. +- Add `:duration_ms` to Logfmt formatter. +- Fixes #216 Log message from supplied message argument when payload contains payload key. ## [4.15.0] diff --git a/Gemfile b/Gemfile index 8995853b..fadf6002 100644 --- a/Gemfile +++ b/Gemfile @@ -1,4 +1,4 @@ -source "http://rubygems.org" +source "https://rubygems.org" gemspec @@ -23,14 +23,15 @@ gem "honeybadger" # [optional] Kafka appender gem "ruby-kafka" # [optional] MongoDB appender +gem "base64" gem "mongo" # [optional] NewRelic appender ( Tests use a mock class ) # gem 'newrelic_rpm' # [optional] Net::TCP appender gem "net_tcp_client" # [optional] Splunk appender -gem "splunk-sdk-ruby" gem "nokogiri" +gem "splunk-sdk-ruby" # [optional] Statsd metrics gem "statsd-ruby" # [optional] legacy Sentry appender @@ -38,8 +39,7 @@ gem "sentry-raven" # [optional] new Sentry appender gem "sentry-ruby" # [optional] Syslog appender when communicating with a remote syslogd over TCP +gem "syslog" gem "syslog_protocol" -group :development do - gem "rubocop", "~> 1.28", "< 1.29" -end +gem "rubocop", "~> 1.28.1", require: false diff --git a/lib/semantic_logger/appender/elasticsearch.rb b/lib/semantic_logger/appender/elasticsearch.rb index 4e3833e1..0b03e545 100644 --- a/lib/semantic_logger/appender/elasticsearch.rb +++ b/lib/semantic_logger/appender/elasticsearch.rb @@ -147,7 +147,7 @@ def initialize(url: "http://localhost:9200", @elasticsearch_args = elasticsearch_args.dup @elasticsearch_args[:url] = url if url && !elasticsearch_args[:hosts] @elasticsearch_args[:logger] = logger - @data_stream = data_stream + @data_stream = data_stream super(level: level, formatter: formatter, filter: filter, application: application, environment: environment, host: host, metrics: false, &block) reopen @@ -177,11 +177,12 @@ def batch(logs) private def write_to_elasticsearch(messages) - bulk_result = if @data_stream - @client.bulk(index: index, body: messages) - else - @client.bulk(body: messages) - end + bulk_result = + if @data_stream + @client.bulk(index: index, body: messages) + else + @client.bulk(body: messages) + end return unless bulk_result["errors"] @@ -191,27 +192,18 @@ def write_to_elasticsearch(messages) def bulk_index(log) expanded_index_name = log.time.strftime("#{index}-#{date_pattern}") - if @data_stream - {"create" => {}} - else - bulk_index = {"index" => {"_index" => expanded_index_name}} - bulk_index["index"].merge!({ "_type" => type }) if version_supports_type? - bulk_index - end + return {"create" => {}} if @data_stream + + bulk_index = {"index" => {"_index" => expanded_index_name}} + bulk_index["index"].merge!({"_type" => type}) if version_supports_type? + bulk_index end def default_formatter - time_key = if @data_stream - "@timestamp" - else - :timestamp - end - + time_key = @data_stream ? "@timestamp" : :timestamp SemanticLogger::Formatters::Raw.new(time_format: :iso_8601, time_key: time_key) end - private - def version_supports_type? Gem::Version.new(::Elasticsearch::VERSION) < Gem::Version.new(7) end diff --git a/lib/semantic_logger/appender/rabbitmq.rb b/lib/semantic_logger/appender/rabbitmq.rb index edee69f4..9fb2d6a4 100644 --- a/lib/semantic_logger/appender/rabbitmq.rb +++ b/lib/semantic_logger/appender/rabbitmq.rb @@ -60,6 +60,10 @@ class Rabbitmq < SemanticLogger::Subscriber # Name of this application to appear in log messages. # Default: SemanticLogger.application # + # metrics: [Boolean] + # Also send metrics only events to rabbitmq. + # Default: true + # # RabbitMQ Parameters: # # rabbitmq_host: [String] @@ -76,13 +80,15 @@ class Rabbitmq < SemanticLogger::Subscriber # Default: nil # # more parameters supported by Bunny: http://rubybunny.info/articles/connecting.html - def initialize(queue_name: "semantic_logger", rabbitmq_host: nil, metrics: false, **args, &block) + def initialize(queue_name: "semantic_logger", rabbitmq_host: nil, + level: nil, formatter: nil, filter: nil, application: nil, environment: nil, host: nil, metrics: true, + **args, &block) @queue_name = queue_name @rabbitmq_args = args.dup @rabbitmq_args[:host] = rabbitmq_host @rabbitmq_args[:logger] = logger - super(level: level, formatter: formatter, filter: filter, application: application, host: host, metrics: metrics, &block) + super(level: level, formatter: formatter, filter: filter, application: application, environment: environment, host: host, metrics: metrics, &block) reopen end diff --git a/lib/semantic_logger/appender/splunk.rb b/lib/semantic_logger/appender/splunk.rb index c361c806..c185f53b 100644 --- a/lib/semantic_logger/appender/splunk.rb +++ b/lib/semantic_logger/appender/splunk.rb @@ -101,10 +101,10 @@ def initialize(index: "main", source_type: nil, **args, &block) # open the handles to resources def reopen # Connect to splunk. Connect is a synonym for creating a Service by hand and calling login. - self.service = Splunk.connect(config) + @service = ::Splunk.connect(config) # The index we are logging to - self.service_index = service.indexes[index] + @service_index = service.indexes[index] end # Log the message to Splunk diff --git a/lib/semantic_logger/appender/syslog.rb b/lib/semantic_logger/appender/syslog.rb index 73f8984f..3425e492 100644 --- a/lib/semantic_logger/appender/syslog.rb +++ b/lib/semantic_logger/appender/syslog.rb @@ -208,7 +208,7 @@ def log(log) # Flush is called by the semantic_logger during shutdown. def flush - @remote_syslog.flush if @remote_syslog&.respond_to?(:flush) + @remote_syslog.flush if @remote_syslog.respond_to?(:flush) end # Returns [SemanticLogger::Formatters::Base] default formatter for this Appender depending on the protocal selected diff --git a/lib/semantic_logger/appender/tcp.rb b/lib/semantic_logger/appender/tcp.rb index 19754507..b112f172 100644 --- a/lib/semantic_logger/appender/tcp.rb +++ b/lib/semantic_logger/appender/tcp.rb @@ -191,7 +191,7 @@ def initialize(separator: "\n", Net::TCPClient.logger = logger Net::TCPClient.logger.name = "Net::TCPClient" - super(level: level, formatter: formatter, filter: filter, application: application, environment: environment, host: host, &block) + super(level: level, formatter: formatter, filter: filter, application: application, environment: environment, host: host, metrics: metrics, &block) reopen end diff --git a/lib/semantic_logger/appender/wrapper.rb b/lib/semantic_logger/appender/wrapper.rb index 38291cf1..f75e0e40 100644 --- a/lib/semantic_logger/appender/wrapper.rb +++ b/lib/semantic_logger/appender/wrapper.rb @@ -1,7 +1,6 @@ # Send log messages to any standard Ruby logging class. # # Forwards logging call to loggers such as Logger, log4r, etc. -# module SemanticLogger module Appender class Wrapper < SemanticLogger::Subscriber @@ -56,15 +55,22 @@ def initialize(logger:, **args, &block) # trace entries are mapped to debug since :trace is not supported by the # Ruby or Rails Loggers def log(log) - @logger.send(log.level == :trace ? :debug : log.level, formatter.call(log, self)) + level = log.level == :trace ? :debug : log.level + @logger.send(level, formatter.call(log, self)) true end # Flush all pending logs to disk. - # Waits for all sent documents to be writted to disk + # Waits for all queued log messages to be written to disk. def flush @logger.flush if @logger.respond_to?(:flush) end + + # Close underlying log + # Waits for all queued log messages to be written to disk. + def close + @logger.close if @logger.respond_to?(:close) + end end end end diff --git a/lib/semantic_logger/appenders.rb b/lib/semantic_logger/appenders.rb index c156964f..3f5f8872 100644 --- a/lib/semantic_logger/appenders.rb +++ b/lib/semantic_logger/appenders.rb @@ -6,6 +6,7 @@ class Appenders < Concurrent::Array def initialize(logger = Processor.logger.dup) @logger = logger @logger.name = self.class.name + super() end def add(**args, &block) @@ -45,18 +46,21 @@ def flush end def close - to_a.each do |appender| + closed_appenders = [] + each do |appender| logger.trace "Closing appender: #{appender.name}" - delete(appender) + appenders << appender appender.flush appender.close rescue Exception => e logger.error "Failed to close appender: #{appender.name}", e end + # Delete appenders outside the #each above which prevents changes during iteration. + closed_appenders.each { |appender| delete(appender) } logger.trace "All appenders closed and removed from appender list" end - # After a fork the appender thread is not running, start it if it is not running. + # After a fork reopen each appender. def reopen each do |appender| next unless appender.respond_to?(:reopen) diff --git a/lib/semantic_logger/base.rb b/lib/semantic_logger/base.rb index d5ffb86d..8fa26a0b 100644 --- a/lib/semantic_logger/base.rb +++ b/lib/semantic_logger/base.rb @@ -342,9 +342,10 @@ def log_internal(level, index, message = nil, payload = nil, exception = nil) # Add result of block to message or payload if not nil if block_given? result = yield(log) - if result.is_a?(String) + case result + when String log.message = log.message.nil? ? result : "#{log.message} -- #{result}" - elsif result.is_a?(Hash) + when Hash log.assign_hash(result) end end diff --git a/lib/semantic_logger/debug_as_trace_logger.rb b/lib/semantic_logger/debug_as_trace_logger.rb index b38bfa5d..4490fe64 100644 --- a/lib/semantic_logger/debug_as_trace_logger.rb +++ b/lib/semantic_logger/debug_as_trace_logger.rb @@ -3,20 +3,9 @@ module SemanticLogger # This is useful for existing gems / libraries that log too much to debug # when most of the debug logging should be at the trace level class DebugAsTraceLogger < Logger - def debug(*args, &block) - trace(*args, &block) - end - - def debug? - trace? - end - - def measure_debug(*args, &block) - measure_trace(*args, &block) - end - - def benchmark_debug(*args, &block) - measure_trace(*args, &block) - end + alias debug trace + alias debug? trace? + alias measure_debug measure_trace + alias benchmark_debug benchmark_trace end end diff --git a/lib/semantic_logger/formatters/raw.rb b/lib/semantic_logger/formatters/raw.rb index 71b0e2a9..44fffa9f 100644 --- a/lib/semantic_logger/formatters/raw.rb +++ b/lib/semantic_logger/formatters/raw.rb @@ -86,7 +86,7 @@ def message # Payload def payload - hash[:payload] = log.payload if log.payload&.respond_to?(:empty?) && !log.payload.empty? + hash[:payload] = log.payload if log.payload.respond_to?(:empty?) && !log.payload.empty? end # Exception diff --git a/lib/semantic_logger/formatters/signalfx.rb b/lib/semantic_logger/formatters/signalfx.rb index 5070af38..3619bed5 100644 --- a/lib/semantic_logger/formatters/signalfx.rb +++ b/lib/semantic_logger/formatters/signalfx.rb @@ -82,7 +82,10 @@ def call(log, logger) self.log = log self.logger = logger - metric; time; value; format_dimensions + metric + time + value + format_dimensions # gauge, counter, or cumulative_counter data = {} @@ -113,7 +116,10 @@ def batch(logs, logger) self.hash = {} self.log = log - metric; time; value; format_dimensions + metric + time + value + format_dimensions if log.duration gauges = (data[:gauge] ||= []) diff --git a/lib/semantic_logger/log.rb b/lib/semantic_logger/log.rb index 8b57fb5a..2827de69 100644 --- a/lib/semantic_logger/log.rb +++ b/lib/semantic_logger/log.rb @@ -144,7 +144,9 @@ def extract_arguments(payload, message = nil) raise(ArgumentError, "payload must be a Hash") unless payload.is_a?(Hash) message = nil if message == "" - return payload if payload.key?(:payload) + if payload.key?(:payload) + return message ? payload.merge(message: message) : payload + end new_payload = {} args = {} diff --git a/lib/semantic_logger/metric/statsd.rb b/lib/semantic_logger/metric/statsd.rb index c1947b7c..5057117d 100644 --- a/lib/semantic_logger/metric/statsd.rb +++ b/lib/semantic_logger/metric/statsd.rb @@ -28,6 +28,7 @@ class Statsd < Subscriber # ) def initialize(url: "udp://localhost:8125") @url = url + super() end def reopen diff --git a/lib/semantic_logger/test/capture_log_events.rb b/lib/semantic_logger/test/capture_log_events.rb index 72acb084..2c5a7392 100644 --- a/lib/semantic_logger/test/capture_log_events.rb +++ b/lib/semantic_logger/test/capture_log_events.rb @@ -4,20 +4,21 @@ module Test # # Example: # - # class UserTest < ActiveSupport::TestCase - # describe User do - # let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new } - # let(:user) { User.new } + # class UserTest < ActiveSupport::TestCase + # describe User do + # let(:logger) { SemanticLogger::Test::CaptureLogEvents.new } + # let(:user) { User.new } # - # it "logs message" do - # user.stub(:logger, capture_logger) do - # user.enable! + # it "logs message" do + # user.stub(:logger, logger) do + # user.enable! + # end + # assert log = logger.events.first + # assert_equal "Hello World", log.message + # assert_equal :info, log.level # end - # assert_equal "Hello World", capture_logger.events.last.message - # assert_equal :info, capture_logger.events.last.level # end # end - # end class CaptureLogEvents < SemanticLogger::Subscriber attr_accessor :events @@ -28,12 +29,27 @@ def initialize(level: :trace, metrics: true) end def log(log) + Logger.call_subscribers(log) @events << log end + # Supports batching of log events + def batch(logs) + @events += log + end + def clear @events.clear end + + # Support silencing of log messages + def level_index + @level_index || SemanticLogger.default_level_index + end + + def to_h + events.map(&:to_h) + end end end end diff --git a/lib/semantic_logger/test/minitest.rb b/lib/semantic_logger/test/minitest.rb index 19f81a5f..52890cab 100644 --- a/lib/semantic_logger/test/minitest.rb +++ b/lib/semantic_logger/test/minitest.rb @@ -3,14 +3,19 @@ module Test module Minitest # Returns [Array] the log events from Semantic Logger # captured whilst executing the supplied block. - def semantic_logger_events(klass = nil, &block) + # + # Notes: + # - All log messages are returned regardless of the global default log level. + def semantic_logger_events(deprecated_klass = nil, klass: deprecated_klass, silence: :trace, &block) logger = SemanticLogger::Test::CaptureLogEvents.new if klass klass.stub(:logger, logger, &block) - else - SemanticLogger.silence(:trace) do + elsif silence + SemanticLogger.silence(silence) do SemanticLogger::Logger.stub(:processor, logger, &block) end + else + SemanticLogger::Logger.stub(:processor, logger, &block) end logger.events end @@ -18,35 +23,65 @@ def semantic_logger_events(klass = nil, &block) # Verify a single log event has all the required attributes. def assert_semantic_logger_event(event, level: nil, name: nil, message: nil, message_includes: nil, payload: nil, payload_includes: nil, + exception: nil, exception_includes: nil, backtrace: nil, thread_name: nil, tags: nil, named_tags: nil, context: nil, + level_index: nil, duration: nil, time: nil, metric: nil, metric_amount: nil, dimensions: nil) - msg = message || message_includes || "no message" - assert event, "Log event missing for message: '#{msg}'" - assert_equal message, event.message if message - assert_includes event.message, message_includes if message_includes - assert_equal name, event.name, -> { "Mismatched log name for message: '#{msg}'" } if name - assert_equal level, event.level, -> { "Mismatched log level for message: '#{msg}'" } if level + assert event, "No log event occurred" + + assert_semantic_logger_entry(event, :message, message) + assert_semantic_logger_entry(event, :name, name) + assert_semantic_logger_entry(event, :level, level) + assert_semantic_logger_entry(event, :thread_name, thread_name) + assert_semantic_logger_entry(event, :tags, tags) + assert_semantic_logger_entry(event, :named_tags, named_tags) + assert_semantic_logger_entry(event, :context, context) + assert_semantic_logger_entry(event, :metric, metric) + assert_semantic_logger_entry(event, :metric_amount, metric_amount) + assert_semantic_logger_entry(event, :dimensions, dimensions) + assert_semantic_logger_entry(event, :level_index, level_index) + assert_semantic_logger_entry(event, :duration, duration) + assert_semantic_logger_entry(event, :time, time) + assert_semantic_logger_entry(event, :exception, exception) + assert_semantic_logger_entry(event, :backtrace, backtrace) + assert_semantic_logger_entry(event, :payload, payload) + + if message_includes + assert_includes( + event.message, + message_includes, + -> { "Expected message to include '#{message_includes}' in log event #{event.inspect}" } + ) + end if payload_includes - payload_includes.each_pair do |key, expected_value| - value = event.payload[key] - if expected_value.nil? - assert_nil value, -> { "Mismatched key: #{key.inspect} in log payload: #{event.payload} for message: '#{msg}'" } - else - assert_equal expected_value, value, -> { "Mismatched key: #{key.inspect} in log payload: #{event.payload} for message: '#{msg}'" } - end + payload_includes.each_pair do |key, expected| + actual = event.payload[key] + assert_semantic_logger_entry(event, "payload #{name}", expected, actual) end - elsif payload - assert_equal payload, event.payload, -> { "Mismatched log payload: #{event.payload} for message: '#{msg}'" } end - assert_equal thread_name, event.thread_name, -> { "Mismatched thread_name for message: '#{msg}'" } if thread_name - assert_equal tags, event.tags, -> { "Mismatched tags for message: '#{msg}'" } if tags - assert_equal named_tags, event.named_tags, -> { "Mismatched named_tags for message: '#{msg}'" } if named_tags - assert_equal context, event.context, -> { "Mismatched context for message: '#{msg}'" } if context - assert_equal metric, event.metric, -> { "Mismatched metric for message: '#{msg}'" } if metric - assert_equal metric_amount, event.metric_amount, -> { "Mismatched metric_amount for message: '#{msg}'" } if metric_amount - assert_equal dimensions, event.dimensions, -> { "Mismatched dimensions for message: '#{msg}'" } if dimensions + if exception_includes + payload_includes.each_pair do |key, expected| + actual = event.exception.send(key) + assert_semantic_logger_entry(event, "Exception #{name}", expected, actual) + end + end + end + + private + + def assert_semantic_logger_entry(event, name, expected, actual = event.send(name)) + return if expected.nil? + + case expected + when :nil + assert_nil actual, "Expected nil #{name} for log event: #{event.to_h.inspect}" + when Class + assert actual.is_a?(expected), -> { "Type #{expected} expected for #{name} in log event: #{event.to_h.inspect}" } + else + assert_equal expected, actual, "Mismatched #{name} for log event: #{event.to_h.inspect}" + end end end end diff --git a/test/appender/graylog_test.rb b/test/appender/graylog_test.rb index a25f429a..843b8d24 100644 --- a/test/appender/graylog_test.rb +++ b/test/appender/graylog_test.rb @@ -4,16 +4,14 @@ module Appender class GraylogTest < Minitest::Test describe SemanticLogger::Appender::Graylog do - before do - @appender = SemanticLogger::Appender::Graylog.new(level: :info) - @message = "AppenderGraylogTest log message" - end + let(:appender) { SemanticLogger::Appender::Graylog.new(level: :info) } + let(:amessage) { "AppenderGraylogTest log message" } (SemanticLogger::LEVELS - %i[info warn error fatal]).each do |level| it "not send :#{level} notifications to Graylog" do hash = nil - @appender.notifier.stub(:notify!, ->(h) { hash = h }) do - @appender.send(level, "AppenderGraylogTest #{level} message") + appender.notifier.stub(:notify!, ->(h) { hash = h }) do + appender.send(level, "AppenderGraylogTest #{level} message") end assert_nil hash end @@ -27,8 +25,8 @@ class GraylogTest < Minitest::Test rescue Exception => e exc = e end - @appender.notifier.stub(:notify!, ->(h) { hash = h }) do - @appender.error "Reading File", exc + appender.notifier.stub(:notify!, ->(h) { hash = h }) do + appender.error "Reading File", exc end assert_equal "Reading File", hash[:short_message] assert_equal "NameError", hash[:exception][:name] @@ -45,8 +43,8 @@ class GraylogTest < Minitest::Test rescue Exception => e exc = e end - @appender.notifier.stub(:notify!, ->(h) { hash = h }) do - @appender.error exc + appender.notifier.stub(:notify!, ->(h) { hash = h }) do + appender.error exc end assert_equal exc.message, hash[:short_message] assert_equal exc.class.to_s, hash[:exception][:name] @@ -58,8 +56,8 @@ class GraylogTest < Minitest::Test it "send notifications to Graylog without exception message" do hash = nil exc = nil - @appender.notifier.stub(:notify!, ->(h) { hash = h }) do - @appender.error exc + appender.notifier.stub(:notify!, ->(h) { hash = h }) do + appender.error exc end assert_equal hash[:short_message], "" assert_nil exc @@ -68,20 +66,20 @@ class GraylogTest < Minitest::Test it "send error notifications to Graylog with severity" do hash = nil - @appender.notifier.stub(:notify!, ->(h) { hash = h }) do - @appender.error @message + appender.notifier.stub(:notify!, ->(h) { hash = h }) do + appender.error amessage end - assert_equal @message, hash[:short_message] + assert_equal amessage, hash[:short_message] assert_equal 3, hash[:level] refute hash[:stack_trace] end it "send notification to Graylog with custom attributes" do hash = nil - @appender.notifier.stub(:notify!, ->(h) { hash = h }) do - @appender.error @message, key1: 1, key2: "a" + appender.notifier.stub(:notify!, ->(h) { hash = h }) do + appender.error amessage, key1: 1, key2: "a" end - assert_equal @message, hash[:short_message] + assert_equal amessage, hash[:short_message] assert_equal 3, hash[:level] refute hash[:stack_trace] assert payload = hash[:payload], hash diff --git a/test/appender/honeybadger_test.rb b/test/appender/honeybadger_test.rb index 60849697..e212c58a 100644 --- a/test/appender/honeybadger_test.rb +++ b/test/appender/honeybadger_test.rb @@ -4,26 +4,19 @@ module Appender class HoneybadgerTest < Minitest::Test describe SemanticLogger::Appender::Honeybadger do - before do - @appender = SemanticLogger::Appender::Honeybadger.new(level: :trace) - @message = "AppenderHoneybadgerTest log message" - SemanticLogger.backtrace_level = :error - end + let(:appender) { SemanticLogger::Appender::Honeybadger.new(level: :trace) } + let(:amessage) { "AppenderHoneybadgerTest log message" } SemanticLogger::LEVELS.each do |level| it "sends #{level} message" do hash = nil Honeybadger.stub(:notify, ->(h) { hash = h }) do - @appender.send(level, @message) + appender.send(level, amessage) end - assert_equal @message, hash[:error_message] + assert_equal amessage, hash[:error_message] assert_equal "SemanticLogger::Appender::Honeybadger", hash[:error_class] - if %i[error fatal].include?(level) - assert hash.key?(:backtrace) - else - refute hash.key?(:backtrace) - end + assert hash.key?(:backtrace) assert_equal true, hash.key?(:context) assert_equal level, hash[:context][:level] end @@ -32,12 +25,12 @@ class HoneybadgerTest < Minitest::Test error = RuntimeError.new("Oh no, Error.") exception = hash = nil Honeybadger.stub(:notify, ->(exc, h) { exception = exc; hash = h }) do - @appender.send(level, @message, error) + appender.send(level, amessage, error) end assert_equal error.class.to_s, exception.class.to_s assert_equal error.message, exception.message - assert_equal @message, hash[:message], hash + assert_equal amessage, hash[:message], hash end end end diff --git a/test/appender/kafka_test.rb b/test/appender/kafka_test.rb index 95f6624f..f9de2f75 100644 --- a/test/appender/kafka_test.rb +++ b/test/appender/kafka_test.rb @@ -3,28 +3,24 @@ module Appender class KafkaTest < Minitest::Test describe SemanticLogger::Appender::Kafka do - before do - @appender = SemanticLogger::Appender::Kafka.new( - seed_brokers: ["localhost:9092"] - ) - @message = "AppenderKafkaTest log message" - end + let(:appender) { SemanticLogger::Appender::Kafka.new(seed_brokers: ["localhost:9092"]) } + let(:amessage) { "AppenderKafkaTest log message" } after do - @appender&.close + appender&.close end it "sends log messages in JSON format" do message = nil options = nil - @appender.send(:producer).stub(:produce, ->(value, *opts) { message = value; options = opts.first }) do - @appender.info(@message) - @appender.flush + appender.send(:producer).stub(:produce, ->(value, *opts) { message = value; options = opts.first }) do + appender.info(amessage) + appender.flush end h = JSON.parse(message) assert_equal "info", h["level"] - assert_equal @message, h["message"] + assert_equal amessage, h["message"] assert_equal "SemanticLogger::Appender::Kafka", h["name"] assert_equal $$, h["pid"] diff --git a/test/appender/mongodb_test.rb b/test/appender/mongodb_test.rb index 77c92114..2af83aba 100644 --- a/test/appender/mongodb_test.rb +++ b/test/appender/mongodb_test.rb @@ -6,29 +6,31 @@ class MongoDBTest < Minitest::Test describe SemanticLogger::Appender::MongoDB do before do skip "Set env var MONGO_HOST to run Mongo tests" unless ENV["MONGO_HOST"] + end - @appender = SemanticLogger::Appender::MongoDB.new( + let(:appender) do + SemanticLogger::Appender::MongoDB.new( uri: "mongodb://#{ENV['MONGO_HOST']}/test", - collection_size: 10 * 1024**2, # 10MB + collection_size: 10 * 1024**2, host: "test", application: "test_application", level: :trace ) - @hash = {tracking_number: 12_345, session_id: "HSSKLEU@JDK767"} - Thread.current.name = "thread" end + let(:ahash) { {tracking_number: 12_345, session_id: "HSSKLEU@JDK767"} } + after do - @appender&.purge_all + appender.purge_all end describe "format logs into documents" do it "handle no arguments" do - @appender.debug - document = @appender.collection.find.first + appender.debug + document = appender.collection.find.first assert_equal :debug, document["level"] assert_nil document["message"] - assert_equal "thread", document["thread"] + assert_equal Thread.current.name, document["thread"] assert document["time"].is_a?(Time) assert_nil document["payload"] assert_equal $$, document["pid"] @@ -37,12 +39,12 @@ class MongoDBTest < Minitest::Test end it "handle named parameters" do - @appender.debug(payload: @hash) + appender.debug(payload: ahash) - document = @appender.collection.find.first + document = appender.collection.find.first assert_equal :debug, document["level"] assert_nil document["message"] - assert_equal "thread", document["thread"] + assert_equal Thread.current.name, document["thread"] assert document["time"].is_a?(Time) assert payload = document["payload"] assert_equal 12_345, payload["tracking_number"], payload @@ -53,12 +55,12 @@ class MongoDBTest < Minitest::Test end it "handle message and payload" do - @appender.debug("hello world", @hash) + appender.debug("hello world", ahash) - document = @appender.collection.find.first + document = appender.collection.find.first assert_equal :debug, document["level"] assert_equal "hello world", document["message"] - assert_equal "thread", document["thread"] + assert_equal Thread.current.name, document["thread"] assert document["time"].is_a?(Time) assert payload = document["payload"] assert_equal 12_345, payload["tracking_number"], payload @@ -69,12 +71,12 @@ class MongoDBTest < Minitest::Test end it "handle message without payload" do - @appender.debug("hello world") + appender.debug("hello world") - document = @appender.collection.find.first + document = appender.collection.find.first assert_equal :debug, document["level"] assert_equal "hello world", document["message"] - assert_equal "thread", document["thread"] + assert_equal Thread.current.name, document["thread"] assert document["time"].is_a?(Time) assert_equal $$, document["pid"] assert_equal "test", document["host"] @@ -86,11 +88,11 @@ class MongoDBTest < Minitest::Test SemanticLogger::LEVELS.each do |level| describe "##{level}" do it "logs" do - @appender.send(level, "hello world -- Calculations", @hash) - document = @appender.collection.find.first + appender.send(level, "hello world -- Calculations", ahash) + document = appender.collection.find.first assert_equal level, document["level"] assert_equal "hello world -- Calculations", document["message"] - assert_equal "thread", document["thread"] + assert_equal Thread.current.name, document["thread"] assert document["time"].is_a?(Time) assert payload = document["payload"] assert_equal 12_345, payload["tracking_number"], payload diff --git a/test/appender/new_relic_test.rb b/test/appender/new_relic_test.rb index 66c96ed1..7de80916 100644 --- a/test/appender/new_relic_test.rb +++ b/test/appender/new_relic_test.rb @@ -6,17 +6,15 @@ module Appender class NewRelicTest < Minitest::Test describe SemanticLogger::Appender::NewRelic do - before do - @appender = SemanticLogger::Appender::NewRelic.new - @message = "AppenderNewRelicTest log message" - end + let(:appender) { SemanticLogger::Appender::NewRelic.new } + let(:amessage) { "AppenderNewRelicTest log message" } (SemanticLogger::LEVELS - %i[error fatal]).each do |level| it "does not send :#{level} notifications to New Relic" do exception = hash = nil NewRelic::Agent.stub(:notice_error, ->(exc, h) { exception = exc; hash = h }) do - @appender.tagged("test") do - @appender.send(level, "AppenderNewRelicTest #{level} message") + appender.tagged("test") do + appender.send(level, "AppenderNewRelicTest #{level} message") end end assert_nil exception @@ -28,12 +26,12 @@ class NewRelicTest < Minitest::Test it "sends :#{level} notifications to New Relic" do exception = hash = nil NewRelic::Agent.stub(:notice_error, ->(exc, h) { exception = exc; hash = h }) do - @appender.tagged("test") do - @appender.send(level, @message) + appender.tagged("test") do + appender.send(level, amessage) end end assert_equal "RuntimeError", exception.class.to_s - assert_equal @message, exception.message + assert_equal amessage, exception.message assert_equal ["test"], hash[:custom_params][:tags] assert_nil hash[:custom_params][:duration] assert hash[:custom_params][:thread], hash.inspect @@ -45,14 +43,14 @@ class NewRelicTest < Minitest::Test NewRelic::Agent.stub(:notice_error, ->(exc, h) { exception = exc; hash = h }) do SemanticLogger.tagged("test") do SemanticLogger.named_tagged(key1: 1, key2: "a") do - @appender.measure_error(message: @message, payload: {key3: 4}) do + appender.measure_error(message: amessage, payload: {key3: 4}) do sleep 0.001 end end end end assert_equal "RuntimeError", exception.class.to_s - assert_equal @message, exception.message + assert_equal amessage, exception.message assert params = hash[:custom_params], hash assert params[:duration], params assert params[:thread], params @@ -70,7 +68,7 @@ class NewRelicTest < Minitest::Test it "does not send metric only notifications" do exception = hash = nil NewRelic::Agent.stub(:notice_error, ->(exc, h) { exception = exc; hash = h }) do - @appender.debug metric: "my/custom/metric", payload: {hello: :world} + appender.debug metric: "my/custom/metric", payload: {hello: :world} end assert_nil exception assert_nil hash diff --git a/test/appender/sentry_ruby_test.rb b/test/appender/sentry_ruby_test.rb index 171592b9..d70ad7fd 100644 --- a/test/appender/sentry_ruby_test.rb +++ b/test/appender/sentry_ruby_test.rb @@ -4,11 +4,8 @@ module Appender class SentryTest < Minitest::Test describe SemanticLogger::Appender::SentryRuby do - before do - @appender = SemanticLogger::Appender::SentryRuby.new(level: :trace) - @message = "AppenderRavenTest log message" - SemanticLogger.backtrace_level = :error - end + let(:appender) { SemanticLogger::Appender::SentryRuby.new(level: :trace) } + let(:amessage) { "AppenderRavenTest log message" } SemanticLogger::LEVELS.each do |level| it "sends #{level} message" do @@ -21,18 +18,12 @@ class SentryTest < Minitest::Test } ::Sentry.stub(:capture_message, capture) do - @appender.send(level, @message) + appender.send(level, amessage) end - assert_equal @message, error_message + assert_equal amessage, error_message assert_equal "SemanticLogger::Appender::SentryRuby", scope.extra[:name] - - if %i[error fatal].include?(level) - assert hash.key?(:backtrace) - else - refute hash.key?(:backtrace) - end - + assert hash.key?(:backtrace) assert_equal level, scope.level end @@ -47,12 +38,12 @@ class SentryTest < Minitest::Test } ::Sentry.stub(:capture_exception, capture) do - @appender.send(level, @message, error) + appender.send(level, amessage, error) end assert_equal error.class.to_s, exception.class.to_s assert_equal error.message, exception.message - assert_equal @message, scope.extra[:message] + assert_equal amessage, scope.extra[:message] assert_equal level, scope.level end end @@ -66,11 +57,8 @@ class SentryTest < Minitest::Test } end - before do - @appender = SemanticLogger::Appender::SentryRuby.new - end - it "uses the tags and arguments" do + appender Sentry.with_scope do |scope| # sentry-only tag scope.set_tags("some" => "tag") @@ -80,7 +68,7 @@ class SentryTest < Minitest::Test SemanticLogger.tagged(transaction_name: "foo", user_id: 42, baz: "quz") do ::Sentry.stub(:capture_message, capture) do args = {username: "joe", fingerprint: ["bar"], other: "unrelated"} - @appender.error("some message", **args) + appender.error("some message", **args) end end end diff --git a/test/appender/sentry_test.rb b/test/appender/sentry_test.rb index 4e26d873..091e33a3 100644 --- a/test/appender/sentry_test.rb +++ b/test/appender/sentry_test.rb @@ -4,26 +4,19 @@ module Appender class SentryTest < Minitest::Test describe SemanticLogger::Appender::Sentry do - before do - @appender = SemanticLogger::Appender::Sentry.new(level: :trace) - @message = "AppenderRavenTest log message" - SemanticLogger.backtrace_level = :error - end + let(:appender) { SemanticLogger::Appender::Sentry.new(level: :trace) } + let(:amessage) { "AppenderRavenTest log message" } SemanticLogger::LEVELS.each do |level| it "sends #{level} message" do error_message = hash = nil Raven.stub(:capture_message, ->(msg, h) { error_message = msg; hash = h }) do - @appender.send(level, @message) + appender.send(level, amessage) end - assert_equal @message, error_message + assert_equal amessage, error_message assert_equal "SemanticLogger::Appender::Sentry", hash[:extra][:name] - if %i[error fatal].include?(level) - assert hash[:extra].key?(:backtrace) - else - refute hash[:extra].key?(:backtrace) - end + assert hash[:extra].key?(:backtrace) assert_equal true, hash.key?(:extra) assert_equal level, hash[:level] end @@ -32,13 +25,13 @@ class SentryTest < Minitest::Test error = RuntimeError.new("Oh no, Error.") exception = hash = nil Raven.stub(:capture_exception, ->(exc, h) { exception = exc; hash = h }) do - @appender.send(level, @message, error) + appender.send(level, amessage, error) end assert_equal error.class.to_s, exception.class.to_s assert_equal error.message, exception.message assert_equal true, hash.key?(:extra) - assert_equal @message, hash[:extra][:message], hash + assert_equal amessage, hash[:extra][:message], hash assert_equal level, hash[:level] end end diff --git a/test/appender/splunk_test.rb b/test/appender/splunk_test.rb index 25705103..1137de5b 100644 --- a/test/appender/splunk_test.rb +++ b/test/appender/splunk_test.rb @@ -1,7 +1,6 @@ require_relative "../test_helper" # Unit Test for SemanticLogger::Appender::Splunk -# module Appender class SplunkTest < Minitest::Test class Mock @@ -14,20 +13,25 @@ def submit(message, event) end describe SemanticLogger::Appender::Splunk do - before do - SemanticLogger::Appender::Splunk.stub_any_instance(:reopen, nil) do - @appender = SemanticLogger::Appender::Splunk.new + let(:appender) do + mock = Module.new do + def self.indexes + {"main" => "main"} + end + end + ::Splunk.stub(:connect, mock) do + SemanticLogger::Appender::Splunk.new end - @message = "AppenderSplunkTest log message" end + let(:amessage) { "AppenderSplunkTest log message" } SemanticLogger::LEVELS.each do |level| it "send #{level}" do mock = Mock.new - @appender.stub(:service_index, mock) do - @appender.send(level, @message) + appender.stub(:service_index, mock) do + appender.send(level, amessage) end - assert_equal @message, mock.message + assert_equal amessage, mock.message assert_equal level, mock.event[:event][:level] refute mock.event[:event][:exception] end @@ -41,10 +45,10 @@ def submit(message, event) end mock = Mock.new - @appender.stub(:service_index, mock) do - @appender.send(level, @message, exc) + appender.stub(:service_index, mock) do + appender.send(level, amessage, exc) end - assert_equal @message, mock.message + assert_equal amessage, mock.message assert exception = mock.event[:event][:exception] assert "NameError", exception[:name] @@ -55,10 +59,10 @@ def submit(message, event) it "sends #{level} custom attributes" do mock = Mock.new - @appender.stub(:service_index, mock) do - @appender.send(level, @message, key1: 1, key2: "a") + appender.stub(:service_index, mock) do + appender.send(level, amessage, key1: 1, key2: "a") end - assert_equal @message, mock.message + assert_equal amessage, mock.message assert event = mock.event[:event], mock.event.ai assert_equal level, event[:level] @@ -70,10 +74,10 @@ def submit(message, event) end it "does not send :trace notifications to Splunk when set to :error" do - mock = Mock.new - @appender.level = :error - @appender.stub(:service_index, mock) do - @appender.trace("AppenderSplunkTest trace message") + mock = Mock.new + appender.level = :error + appender.stub(:service_index, mock) do + appender.trace("AppenderSplunkTest trace message") end assert_nil mock.event assert_nil mock.message diff --git a/test/appender/tcp_test.rb b/test/appender/tcp_test.rb index 74514fb4..7972b979 100644 --- a/test/appender/tcp_test.rb +++ b/test/appender/tcp_test.rb @@ -4,26 +4,29 @@ module Appender class TcpTest < Minitest::Test describe SemanticLogger::Appender::Tcp do - before do - Net::TCPClient.stub_any_instance(:connect, true) do - @appender = SemanticLogger::Appender::Tcp.new(server: "localhost:8088") - end - @appender.tcp_client.instance_eval do + let(:appender) do + appender = + Net::TCPClient.stub_any_instance(:connect, true) do + SemanticLogger::Appender::Tcp.new(server: "localhost:8088") + end + appender.tcp_client.instance_eval do def retry_on_connection_failure yield end end - @message = "AppenderTcpTest log message" + appender end + let(:amessage) { "AppenderTcpTest log message" } + SemanticLogger::LEVELS.each do |level| it "send #{level}" do data = nil - @appender.tcp_client.stub(:write, ->(d) { data = d }) do - @appender.send(level, @message) + appender.tcp_client.stub(:write, ->(d) { data = d }) do + appender.send(level, amessage) end hash = JSON.parse(data) - assert_equal @message, hash["message"] + assert_equal amessage, hash["message"] assert_equal level.to_s, hash["level"] refute hash["stack_trace"] end @@ -36,8 +39,8 @@ def retry_on_connection_failure exc = e end data = nil - @appender.tcp_client.stub(:write, ->(d) { data = d }) do - @appender.send(level, "Reading File", exc) + appender.tcp_client.stub(:write, ->(d) { data = d }) do + appender.send(level, "Reading File", exc) end hash = JSON.parse(data) assert "Reading File", hash["message"] @@ -49,11 +52,11 @@ def retry_on_connection_failure it "send #{level} custom attributes" do data = nil - @appender.tcp_client.stub(:write, ->(d) { data = d }) do - @appender.send(level, @message, key1: 1, key2: "a") + appender.tcp_client.stub(:write, ->(d) { data = d }) do + appender.send(level, amessage, key1: 1, key2: "a") end hash = JSON.parse(data) - assert_equal @message, hash["message"] + assert_equal amessage, hash["message"] assert_equal level.to_s, hash["level"] refute hash["stack_trace"] assert payload = hash["payload"], hash diff --git a/test/appender/udp_test.rb b/test/appender/udp_test.rb index 60891268..2d05348f 100644 --- a/test/appender/udp_test.rb +++ b/test/appender/udp_test.rb @@ -4,19 +4,17 @@ module Appender class UdpTest < Minitest::Test describe SemanticLogger::Appender::Udp do - before do - @appender = SemanticLogger::Appender::Udp.new(server: "localhost:8088") - @message = "AppenderUdpTest log message" - end + let(:appender) { SemanticLogger::Appender::Udp.new(server: "localhost:8088") } + let(:amessage) { "AppenderUdpTest log message" } SemanticLogger::LEVELS.each do |level| it "send #{level}" do data = nil - @appender.socket.stub(:send, ->(d, _flags) { data = d }) do - @appender.send(level, @message) + appender.socket.stub(:send, ->(d, _flags) { data = d }) do + appender.send(level, amessage) end hash = JSON.parse(data) - assert_equal @message, hash["message"] + assert_equal amessage, hash["message"] assert_equal level.to_s, hash["level"] refute hash["stack_trace"] end @@ -29,8 +27,8 @@ class UdpTest < Minitest::Test exc = e end data = nil - @appender.socket.stub(:send, ->(d, _flags) { data = d }) do - @appender.send(level, "Reading File", exc) + appender.socket.stub(:send, ->(d, _flags) { data = d }) do + appender.send(level, "Reading File", exc) end hash = JSON.parse(data) assert "Reading File", hash["message"] @@ -42,11 +40,11 @@ class UdpTest < Minitest::Test it "send #{level} custom attributes" do data = nil - @appender.socket.stub(:send, ->(d, _flags) { data = d }) do - @appender.send(level, @message, key1: 1, key2: "a") + appender.socket.stub(:send, ->(d, _flags) { data = d }) do + appender.send(level, amessage, key1: 1, key2: "a") end hash = JSON.parse(data) - assert_equal @message, hash["message"] + assert_equal amessage, hash["message"] assert_equal level.to_s, hash["level"] refute hash["stack_trace"] assert payload = hash["payload"], hash diff --git a/test/appender/wrapper_test.rb b/test/appender/wrapper_test.rb index e02eb935..be99f5fe 100644 --- a/test/appender/wrapper_test.rb +++ b/test/appender/wrapper_test.rb @@ -1,7 +1,6 @@ require_relative "../test_helper" -# Unit Test for SemanticLogger::Appender::Wrapper -# +# Unit Test for Appender::WrapperTest module Appender class WrapperTest < Minitest::Test # Looks like a standard Ruby Logger or Rails Logger @@ -23,7 +22,7 @@ def #{level.downcase}(message = nil, progname = nil) end def #{level}? - @true + true end LEVEL_CODE end @@ -34,60 +33,72 @@ def flush end describe SemanticLogger::Appender::Wrapper do - before do - SemanticLogger.default_level = :trace - SemanticLogger.backtrace_level = :trace - - @time = Time.new - @mock_logger = MockLogger.new - @appender = SemanticLogger::Appender::Wrapper.new(logger: @mock_logger) - @hash = {session_id: "HSSKLEU@JDK767", tracking_number: 12_345} - @hash_str = @hash.inspect.sub("{", '\\{').sub("}", '\\}') - @thread_name = Thread.current.name - @file_name_reg_exp = ' wrapper_test.rb:\d+' + let(:mock_logger) { MockLogger.new } + let(:appender) { SemanticLogger::Appender::Wrapper.new(logger: mock_logger) } + let(:ahash) { {session_id: "HSSKLEU@JDK767", tracking_number: 12_345} } + let(:hash_str) { ahash.inspect.sub("{", '\\{').sub("}", '\\}') } + let(:file_name_reg_exp) { ' wrapper_test.rb:\d+' } + let(:log) do + log = SemanticLogger::Log.new("User", :info) + log.message = "hello world" + log.level = :info + log + end + let(:backtrace) do + [ + "test/formatters/default_test.rb:35:in `block (2 levels) in '" + ] end - describe "format logs into text form" do - it "logs blank data" do - @appender.debug - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{@thread_name}#{@file_name_reg_exp}\] SemanticLogger::Appender::Wrapper/, @mock_logger.message) - end - - it "logs message" do - @appender.debug("hello world") - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{@thread_name}#{@file_name_reg_exp}\] SemanticLogger::Appender::Wrapper -- hello world/, @mock_logger.message) + describe "logs" do + it "blank data" do + log.message = nil + log.level = :debug + appender.log(log.freeze) + assert_match( + /\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+\] User/, mock_logger.message + ) end - it "logs message and payload" do - @appender.debug("hello world", @hash) - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{@thread_name}#{@file_name_reg_exp}\] SemanticLogger::Appender::Wrapper -- hello world -- #{@hash_str}/, @mock_logger.message) + it "message" do + appender.log(log.freeze) + assert_match( + /\d+-\d+-\d+ \d+:\d+:\d+.\d+ I \[\d+:\w+\] User -- hello world/, mock_logger.message + ) end - it "logs named parameters" do - @appender.debug(message: "hello world", payload: @hash) - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{@thread_name}#{@file_name_reg_exp}\] SemanticLogger::Appender::Wrapper -- hello world -- #{@hash_str}/, @mock_logger.message) + it "backtrace" do + log.level = :warn + log.backtrace = backtrace + appender.log(log.freeze) + assert_match( + /\d+-\d+-\d+ \d+:\d+:\d+.\d+ W \[\d+:\w+\ default_test.rb:35\] User -- hello world/, mock_logger.message + ) end - end - describe "for each log level" do - before do - @appender = SemanticLogger.add_appender(logger: @mock_logger) - @logger = SemanticLogger[WrapperTest] + it "payload" do + log.level = :error + log.payload = ahash + appender.log(log.freeze) + assert_match( + /\d+-\d+-\d+ \d+:\d+:\d+.\d+ E \[\d+:\w+\] User -- hello world -- #{hash_str}/, mock_logger.message + ) end - after do - SemanticLogger.remove_appender(@appender) + it "trace as debug" do + log.level = :trace + appender.log(log.freeze) + assert_match( + /\d+-\d+-\d+ \d+:\d+:\d+.\d+ T \[\d+:\w+\] User -- hello world/, mock_logger.message + ) end - # Ensure that any log level can be logged - Logger::Severity.constants.each do |level| - it "log #{level.downcase.to_sym}" do - level_char = level[0].upcase - level_char = "E" if level_char == "U" - @logger.send(level.downcase.to_sym, "hello world", @hash) - SemanticLogger.flush - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ #{level_char} \[\d+:#{@thread_name}#{@file_name_reg_exp}\] Appender::WrapperTest -- hello world -- #{@hash_str}/, @mock_logger.message) - end + it "fatal" do + log.level = :fatal + appender.log(log.freeze) + assert_match( + /\d+-\d+-\d+ \d+:\d+:\d+.\d+ F \[\d+:\w+\] User -- hello world/, mock_logger.message + ) end end end diff --git a/test/appenders_test.rb b/test/appenders_test.rb index fae424dd..6ffdc01b 100644 --- a/test/appenders_test.rb +++ b/test/appenders_test.rb @@ -2,10 +2,9 @@ class AppendersTest < Minitest::Test describe SemanticLogger::Appenders do - let :appenders do - logger = SemanticLogger["Test"] - SemanticLogger::Appenders.new(logger) - end + let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new } + let(:appenders) { SemanticLogger::Appenders.new(capture_logger) } + let(:logger) { SemanticLogger::Test::CaptureLogEvents.new } describe "#add" do it "adds file appender" do @@ -90,6 +89,16 @@ class AppendersTest < Minitest::Test assert_equal 2, appenders.size end + + it "adds batch proxy" do + appender = appenders.add(appender: logger, batch: true) + assert_instance_of SemanticLogger::Appender::AsyncBatch, appender + end + + # it "adds async proxy" do + # appender = appenders.add(appender: logger, async: true) + # assert_instance_of SemanticLogger::Appender::Async, appender + # end end end end diff --git a/test/concerns/compatibility_test.rb b/test/concerns/compatibility_test.rb index 40ae60e5..c96a33dc 100644 --- a/test/concerns/compatibility_test.rb +++ b/test/concerns/compatibility_test.rb @@ -1,97 +1,121 @@ require_relative "../test_helper" -class TestLogger < Minitest::Test +class CompatibilityTest < Minitest::Test describe SemanticLogger::Logger do - include InMemoryAppenderHelper + let(:logger) { SemanticLogger["TestLogger"] } it "#add" do - logger.add(Logger::INFO, "hello world", "progname") { "Data" } + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.add(Logger::INFO, "hello world", "progname") { "Data" } + end - assert log = log_message assert_equal "hello world -- progname -- Data", log.message assert_equal :info, log.level end it "#log" do - logger.log(Logger::FATAL, "hello world", "progname") { "Data" } + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.log(Logger::FATAL, "hello world", "progname") { "Data" } + end - assert log = log_message assert_equal "hello world -- progname -- Data", log.message assert_equal :fatal, log.level end describe "#info" do it "logs message" do - logger.info("hello1") + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.info("hello1") + end - assert log = log_message assert_equal "hello1", log.message assert_equal :info, log.level end it "logs 2 messages" do - logger.info("hello1", "hello2") + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.info("hello1", "hello2") + end - assert log = log_message assert_equal "hello1 -- hello2", log.message assert_equal :info, log.level end it "logs non-string" do - logger.info("hello1", true) + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.info("hello1", true) + end - assert log = log_message assert_equal "hello1 -- true", log.message assert_equal :info, log.level end it "logs block result" do - logger.info("hello1", true) { "Data" } + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.info("hello1", true) { "Data" } + end - assert log = log_message assert_equal "hello1 -- true -- Data", log.message assert_equal :info, log.level end end it "#unknown" do - logger.unknown("hello world") { "Data" } + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.unknown("hello world") { "Data" } + end - assert log = log_message assert_equal "hello world -- Data", log.message assert_equal :error, log.level assert_equal "TestLogger", log.name end it "#unknown? as error?" do - SemanticLogger.default_level = :error + logger.level = :error assert logger.unknown? - logger.log(Logger::UNKNOWN, "hello world", "progname") { "Data" } + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.log(Logger::UNKNOWN, "hello world", "progname") { "Data" } + end - assert log = log_message assert_equal "hello world -- progname -- Data", log.message assert_equal :error, log.level end it "#unknown? as error? when false" do - SemanticLogger.default_level = :fatal + logger.level = :fatal refute logger.unknown? - logger.log(Logger::UNKNOWN, "hello world", "progname") { "Data" } + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.log(Logger::UNKNOWN, "hello world", "progname") { "Data" } + end - refute log_message + refute log end it "#silence_logger" do - logger.silence_logger do - logger.info "hello world" + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.silence_logger do + logger.info "hello world" + end end - refute log_message + refute log end it "#<< as info" do - logger << "hello world" + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger << "hello world" + end - assert log = log_message assert_equal "hello world", log.message assert_equal :info, log.level end @@ -108,12 +132,13 @@ class TestLogger < Minitest::Test end it "#sev_threshold= as #level=" do - assert_equal :trace, logger.level + logger.level = :trace logger.sev_threshold = Logger::DEBUG assert_equal :debug, logger.level end it "#sev_threshold as #level" do + logger.level = :trace assert_equal :trace, logger.level assert_equal :trace, logger.sev_threshold end @@ -132,18 +157,22 @@ class TestLogger < Minitest::Test it "#close NOOP" do logger.close - logger.info("hello world") + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.info("hello world") + end - assert log = log_message assert_equal "hello world", log.message assert_equal :info, log.level end it "#reopen NOOP" do logger.reopen - logger.info("hello world") + log = nil + SemanticLogger::Logger.processor.stub(:log, ->(_log) { log = _log }) do + logger.info("hello world") + end - assert log = log_message assert_equal "hello world", log.message assert_equal :info, log.level end diff --git a/test/debug_as_trace_logger_test.rb b/test/debug_as_trace_logger_test.rb index 38ff690d..5eb97f87 100644 --- a/test/debug_as_trace_logger_test.rb +++ b/test/debug_as_trace_logger_test.rb @@ -1,34 +1,20 @@ require_relative "test_helper" class DebugAsTraceLoggerTest < Minitest::Test - describe SemanticLogger::Logger do - describe ".level?" do - let :logger do - SemanticLogger::DebugAsTraceLogger.new("TestLogger") - end - - it "return true for debug? with :trace level" do - SemanticLogger.default_level = :trace - assert_equal :trace, logger.level - assert_equal true, logger.debug? - assert_equal true, logger.trace? - end + # Keep log calls in memory + class LogTester < SemanticLogger::DebugAsTraceLogger + attr_accessor :events - it "return false for debug? with global :debug level" do - SemanticLogger.default_level = :debug - assert_equal :debug, logger.level, logger - assert logger.info?, logger.inspect - refute logger.debug?, logger.inspect - refute logger.trace?, logger.inspect - end + def log(log) + (@events ||= []) << log + end + end - it "return true for debug? with global :info level" do - SemanticLogger.default_level = :info - assert_equal :info, logger.level, logger.inspect - refute logger.debug?, logger.inspect - refute logger.trace?, logger.inspect - end + describe SemanticLogger::Logger do + let(:logger) { LogTester.new("TestLogger") } + let(:payload) { {session_id: "HSSKLEU@JDK767", tracking_number: 12_345, message: "Message from payload"} } + describe ".level?" do it "return false for debug? with instance :debug level" do logger.level = :debug assert_equal :debug, logger.level, logger.inspect @@ -45,35 +31,29 @@ class DebugAsTraceLoggerTest < Minitest::Test end describe "log" do - include InMemoryAppenderHelper - - let :logger do - SemanticLogger::DebugAsTraceLogger.new("TestLogger") - end - it "not log trace when level is debug" do logger.level = :debug logger.trace("hello world", payload) { "Calculations" } - refute log_message + refute logger.events end it "not log debug when level is debug" do logger.level = :debug logger.debug("hello world", payload) { "Calculations" } - refute log_message + refute logger.events end it "map debug to trace" do logger.level = :trace logger.debug("hello world") - assert log = log_message + assert log = logger.events.first assert_equal :trace, log.level end it "log trace as trace" do logger.level = :trace logger.trace("hello world", payload) { "Calculations" } - assert log = log_message + assert log = logger.events.first assert_equal :trace, log.level end end diff --git a/test/formatters_test.rb b/test/formatters_test.rb index 671753e9..a155f145 100644 --- a/test/formatters_test.rb +++ b/test/formatters_test.rb @@ -3,13 +3,8 @@ class FormattersTest < Minitest::Test describe SemanticLogger::Formatters do describe ".factory" do - let :log do - SemanticLogger::Log.new("Test", :info) - end - - let :appender do - SemanticLogger::Appender::IO.new($stdout) - end + let(:log) { SemanticLogger::Log.new("Test", :info) } + let(:appender) { SemanticLogger::Appender::IO.new($stdout) } it "from a symbol" do assert formatter = SemanticLogger::Formatters.factory(:raw) diff --git a/test/loggable_test.rb b/test/loggable_test.rb index 41bc1111..b052e37f 100644 --- a/test/loggable_test.rb +++ b/test/loggable_test.rb @@ -1,10 +1,6 @@ require_relative "test_helper" require "stringio" -class TestAttribute - include SemanticLogger::Loggable -end - class AppenderFileTest < Minitest::Test module Perform def perform @@ -27,6 +23,10 @@ class Subclass < Base include Process end + class TestAttribute + include SemanticLogger::Loggable + end + describe SemanticLogger::Loggable do describe "inheritance" do it "should give child classes their own logger" do @@ -70,31 +70,13 @@ class Subclass < Base end end - describe "logger" do - include InMemoryAppenderHelper - - describe "for each log level" do - # Ensure that any log level can be logged - SemanticLogger::LEVELS.each do |level| - it "logs #{level} information with class attribute" do - TestAttribute.logger.send(level, "hello #{level}", payload) - - assert log = log_message - assert_equal "hello #{level}", log.message - assert_equal level, log.level - assert_equal "TestAttribute", log.name - assert_equal payload, log.payload - end + describe "sample class" do + it "has class level logger" do + TestAttribute.logger.is_a?(SemanticLogger::Logger) + end - it "log #{level} information with instance attribute" do - TestAttribute.new.logger.send(level, "hello #{level}", payload) - assert log = log_message - assert_equal "hello #{level}", log.message - assert_equal level, log.level - assert_equal "TestAttribute", log.name - assert_equal payload, log.payload - end - end + it "has instance level logger" do + TestAttribute.new.logger.is_a?(SemanticLogger::Logger) end end end diff --git a/test/logger_test.rb b/test/logger_test.rb index f2988aff..8c6e2249 100644 --- a/test/logger_test.rb +++ b/test/logger_test.rb @@ -3,11 +3,7 @@ # Unit Test for SemanticLogger::Logger class LoggerTest < Minitest::Test describe SemanticLogger::Logger do - include InMemoryAppenderHelper - - let :dimensions do - {action: "hit", user: "jbloggs", state: "FL"} - end + let(:logger) { SemanticLogger::Test::CaptureLogEvents.new } # Complex filters module ComplexFilter @@ -20,270 +16,26 @@ def self.call(log) # SemanticLogger::LEVELS.each do |level| [:debug].each do |level| describe "##{level}" do - describe "positional parameter" do - it "logs message" do - logger.send(level, "hello world") - - assert log = log_message - assert_equal "hello world", log.message - end - - it "adds message from block" do - logger.send(level, "hello world") { "Calculations" } - - assert log = log_message - assert_equal "hello world -- Calculations", log.message - end - - it "logs message and payload" do - logger.send(level, "hello world", payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs simple metric" do - metric_name = "/my/own/metric" - logger.send(level, "hello world", metric: metric_name) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal metric_name, log.metric - assert_nil log.payload - assert_nil log.duration - end - - it "logs duration" do - logger.send(level, "hello world", duration: 20) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal 20, log.duration - assert_nil log.payload - assert_nil log.metric - end - - it "logs with backtrace" do - SemanticLogger.stub(:backtrace_level_index, 0) do - logger.send(level, "hello world", payload) { "Calculations" } - - assert log = log_message - assert_equal "hello world -- Calculations", log.message - assert_equal payload, log.payload - assert log.backtrace - assert log.backtrace.size.positive?, log.backtrace - end - end - - it "logs with backtrace and exception" do - SemanticLogger.stub(:backtrace_level_index, 0) do - exc = RuntimeError.new("Test") - logger.send(level, "hello world", exc) - - assert log = log_message - assert_equal "hello world", log.message - assert log.backtrace - assert log.backtrace.size.positive?, log.backtrace - - assert log.exception - refute log.exception.backtrace - assert_equal "RuntimeError", log.exception.class.name - end - end - end - - describe "keyword arguments" do - it "logs message" do - logger.send(level, message: "hello world") - - assert log = log_message - assert_equal "hello world", log.message - end - - it "logs payload and message" do - logger.send(level, message: "hello world", payload: payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs payload and message without payload arg" do - logger.send(level, "hello world", **payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs message without modifying the supplied hash" do - details = {message: "hello world"} - logger.send(level, details) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal "hello world", details[:message] - end - - it "logs payload and message from block" do - logger.send(level) { {message: "hello world", payload: payload} } - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs payload from block" do - logger.send(level) { {"test_key1" => "hello world", "test_key2" => payload} } - - assert log = log_message - assert_equal log.payload, "test_key1" => "hello world", "test_key2" => payload - end - - it "logs payload only" do - logger.send(level, payload: payload) - - assert log = log_message - refute log.message - assert_equal payload, log.payload - end - - it "logs duration" do - logger.send(level, duration: 123.44, message: "hello world", payload: payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - assert_equal 123.44, log.duration - end - - it "does not log when below min_duration" do - logger.send(level, min_duration: 200, duration: 123.45, message: "hello world", payload: {tracking_number: "123456", even: 2, more: "data"}) - - refute log_message - end - - it "logs metric" do - metric_name = "/my/custom/metric" - logger.send(level, metric: metric_name, duration: 123.44, message: "hello world", payload: payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - assert_equal 123.44, log.duration - assert_equal metric_name, log.metric - end - - describe "metrics appender" do - let :appender do - InMemoryMetricsAppender.new - end - - it "logs metric only events" do - metric_name = "/my/custom/metric" - logger.send(level, metric: metric_name, dimensions: dimensions) - - assert log = log_message - assert_equal metric_name, log.metric - assert_equal dimensions, log.dimensions - refute log.message - end - end - - it "for compatibility handles random payload logged as keyword arguments" do - logger.send(level, payload) - - assert log = log_message - assert_equal "Message from payload", log.message - refute log.exception - refute log.metric - payload_without_message = payload.dup - payload_without_message.delete(:message) - assert_equal payload_without_message, log.payload - end - end - describe "#filter" do - describe "at the appender level" do - it "Proc" do - appender.filter = ->(log) { (/\AExclude/ =~ log.message).nil? } - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - - refute log_message - end - - it "Module" do - appender.filter = ComplexFilter - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - - refute log_message - end - - it "RegExp" do - appender.filter = ->(log) { (/\AExclude/ =~ log.message).nil? } - logger.send(level, "Exclude this log message", @hash) { "Calculations" } + it "Proc" do + logger.filter = ->(log) { (/\AExclude/ =~ log.message).nil? } + logger.send(level, "Exclude this log message", @hash) { "Calculations" } - refute log_message - end + assert logger.events.empty? end - describe "at the logger level" do - it "Proc" do - logger.filter = ->(log) { (/\AExclude/ =~ log.message).nil? } - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - - refute log_message - end - - it "Module" do - logger.filter = ComplexFilter - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - - refute log_message - end - - it "RegExp" do - logger.filter = ->(log) { (/\AExclude/ =~ log.message).nil? } - logger.send(level, "Exclude this log message", @hash) { "Calculations" } + it "Module" do + logger.filter = ComplexFilter + logger.send(level, "Exclude this log message", @hash) { "Calculations" } - refute log_message - end + assert logger.events.empty? end - describe "on the logger initializer" do - describe "Proc" do - let :log_filter do - ->(log) { (/\AExclude/ =~ log.message).nil? } - end - - it "filters" do - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - refute log_message - end - end - - describe "Module" do - let :log_filter do - ComplexFilter - end - - it "filters" do - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - refute log_message - end - end - - describe "RegExp" do - let :log_filter do - /\ALogger/ - end + it "RegExp" do + logger.filter = ->(log) { (/\AExclude/ =~ log.message).nil? } + logger.send(level, "Exclude this log message", @hash) { "Calculations" } - it "filters" do - logger.send(level, "Exclude this log message", @hash) { "Calculations" } - refute log_message - end - end + assert logger.events.empty? end end end @@ -291,10 +43,10 @@ def self.call(log) describe "when level is too high" do it "does not log" do - SemanticLogger.default_level = :error + logger.level = :error logger.info("Exclude this log message") - refute log_message + assert logger.events.empty? end end @@ -314,26 +66,12 @@ def self.call(log) describe "#level?" do it "return true for debug? with :trace level" do - SemanticLogger.default_level = :trace + logger.level = :trace assert_equal :trace, logger.level assert_equal true, logger.debug? assert_equal true, logger.trace? end - it "return false for debug? with global :debug level" do - SemanticLogger.default_level = :debug - assert_equal :debug, logger.level, logger.inspect - assert_equal true, logger.debug?, logger.inspect - assert_equal false, logger.trace?, logger.inspect - end - - it "return true for debug? with global :info level" do - SemanticLogger.default_level = :info - assert_equal :info, logger.level, logger.inspect - assert_equal false, logger.debug?, logger.inspect - assert_equal false, logger.trace?, logger.inspect - end - it "return false for debug? with instance :debug level" do logger.level = :debug assert_equal :debug, logger.level, logger.inspect @@ -350,16 +88,11 @@ def self.call(log) end describe ".tagged" do - it "sets global defaults" do - assert_equal [], SemanticLogger.tags - assert_equal 0, SemanticLogger.backtrace_level_index - end - it "add tags to log entries" do logger.tagged("12345", "DJHSFK") do logger.info("hello world") - assert log = log_message + assert log = logger.events.first assert_equal "hello world", log.message assert_equal %w[12345 DJHSFK], log.tags end @@ -371,7 +104,7 @@ def self.call(log) assert_equal ["First Level", "tags", "Second Level"], logger.tags logger.info("hello world") - assert log = log_message + assert log = logger.events.first assert_equal "hello world", log.message assert_equal ["First Level", "tags", "Second Level"], log.tags end @@ -398,7 +131,7 @@ def self.call(log) logger.tagged("", %w[12345 DJHSFK], nil) do logger.info("hello world") - assert log = log_message + assert log = logger.events.first assert_equal "hello world", log.message assert_equal %w[12345 DJHSFK], log.tags end @@ -408,7 +141,7 @@ def self.call(log) logger.tagged(%w[first second]) do logger.info("hello world") - assert log = log_message + assert log = logger.events.first assert_equal "hello world", log.message assert_equal %w[first second], log.tags end diff --git a/test/measure_test.rb b/test/measure_test.rb index fbc8b40e..6589e855 100644 --- a/test/measure_test.rb +++ b/test/measure_test.rb @@ -2,44 +2,33 @@ class MeasureTest < Minitest::Test describe "Measure" do - include InMemoryAppenderHelper + let(:appender) { SemanticLogger::Test::CaptureLogEvents.new } + let(:payload) { {session_id: "HSSKLEU@JDK767", tracking_number: 12_345, message: "Message from payload"} } # Ensure that any log level can be measured and logged SemanticLogger::LEVELS.each do |level| measure_level = "measure_#{level}".to_sym describe "##{measure_level}" do - it ":message" do - assert_equal "result", appender.send(measure_level, "hello world") { "result" } + it "logs" do + assert_equal "result", appender.send(measure_level, "hello world", payload: payload) { "result" } - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message - end - - it ":level" do - assert_equal "result", appender.send(measure_level, "hello world") { "result" } - - assert log = log_message assert_equal level, log.level - end - - it ":payload" do - assert_equal "result", appender.send(measure_level, "hello world", payload: payload) { "result" } - - assert log = log_message assert_equal payload, log.payload end describe ":min_duration" do it "not log when faster" do assert_equal "result", appender.send(measure_level, "hello world", min_duration: 2000) { "result" } - refute log_message + assert appender.events.empty? end it "log when slower" do assert_equal "result", appender.send(measure_level, "hello world", min_duration: 200, payload: payload) { sleep 0.5; "result" } - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message end end @@ -49,7 +38,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, "hello world", payload: payload) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message assert_equal level, log.level @@ -60,7 +49,7 @@ class MeasureTest < Minitest::Test appender.measure(level, "hello world", payload: payload, on_exception_level: :fatal) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message assert_equal :fatal, log.level @@ -72,7 +61,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, "hello world") { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message end @@ -82,7 +71,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, "hello world", log_exception: :full) { raise "Test" } end - assert log = log_message + assert log = appender.events.first assert log.exception.is_a?(RuntimeError) assert log.exception.backtrace assert_equal level, log.level @@ -94,7 +83,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, "hello world", log_exception: :partial) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message end @@ -104,7 +93,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, "hello world", log_exception: :none) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world", log.message end @@ -114,7 +103,7 @@ class MeasureTest < Minitest::Test metric_name = "/my/custom/metric" assert_equal "result", appender.send(measure_level, "hello world", metric: metric_name) { "result" } - assert log = log_message + assert log = appender.events.first assert_equal metric_name, log.metric end @@ -122,7 +111,7 @@ class MeasureTest < Minitest::Test SemanticLogger.stub(:backtrace_level_index, 0) do assert_equal "result", appender.send(measure_level, "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert log.backtrace assert log.backtrace.size.positive? @@ -138,33 +127,33 @@ class MeasureTest < Minitest::Test it ":message" do assert_equal "result", appender.measure(level, "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message end it ":level" do assert_equal "result", appender.measure(level, "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert_equal level, log.level end it ":payload" do assert_equal "result", appender.measure(level, "hello world", payload: payload) { "result" } - assert log = log_message + assert log = appender.events.first assert_equal payload, log.payload end describe ":min_duration" do it "not log when faster" do assert_equal "result", appender.measure(level, "hello world", min_duration: 2000) { "result" } - refute log_message + assert appender.events.empty? end it "log when slower" do assert_equal "result", appender.measure(level, "hello world", min_duration: 200, payload: payload) { sleep 0.5; "result" } - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message end end @@ -174,7 +163,7 @@ class MeasureTest < Minitest::Test appender.measure(level, "hello world", payload: payload) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message assert_equal level, log.level @@ -185,7 +174,7 @@ class MeasureTest < Minitest::Test appender.measure(level, "hello world", payload: payload, on_exception_level: :fatal) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message assert_equal :fatal, log.level @@ -195,7 +184,7 @@ class MeasureTest < Minitest::Test metric_name = "/my/custom/metric" assert_equal "result", appender.measure(level, "hello world", metric: metric_name) { "result" } - assert log = log_message + assert log = appender.events.first assert_equal metric_name, log.metric end @@ -203,7 +192,7 @@ class MeasureTest < Minitest::Test SemanticLogger.stub(:backtrace_level_index, 0) do assert_equal "result", appender.measure(level, "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert log.backtrace assert log.backtrace.size.positive? @@ -219,34 +208,34 @@ class MeasureTest < Minitest::Test it ":message" do assert_equal "result", appender.send(measure_level, message: "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message end it ":level" do assert_equal "result", appender.send(measure_level, message: "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert_equal level, log.level end it ":payload" do assert_equal "result", appender.send(measure_level, message: "hello world", payload: payload) { "result" } - assert log = log_message + assert log = appender.events.first assert_equal payload, log.payload end describe ":min_duration" do it "not log when faster" do assert_equal "result", appender.send(measure_level, message: "hello world", min_duration: 2000) { "result" } - refute log_message + assert appender.events.empty? end it "log when slower" do assert_equal "result", appender.send(measure_level, message: "hello world", min_duration: 200, payload: payload) { sleep 0.5; "result" } - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message end end @@ -256,7 +245,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, message: "hello world", payload: payload) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message assert_equal level, log.level @@ -267,7 +256,7 @@ class MeasureTest < Minitest::Test appender.send(measure_level, message: "hello world", payload: payload, on_exception_level: :fatal) { raise "Test" } end - assert log = log_message + assert log = appender.events.first refute log.exception assert_equal "hello world -- Exception: RuntimeError: Test", log.message assert_equal :fatal, log.level @@ -277,7 +266,7 @@ class MeasureTest < Minitest::Test metric_name = "/my/custom/metric" assert_equal "result", appender.send(measure_level, message: "hello world", metric: metric_name) { "result" } - assert log = log_message + assert log = appender.events.first assert_equal metric_name, log.metric end @@ -285,7 +274,7 @@ class MeasureTest < Minitest::Test SemanticLogger.stub(:backtrace_level_index, 0) do assert_equal "result", appender.send(measure_level, message: "hello world") { "result" } - assert log = log_message + assert log = appender.events.first assert log.backtrace assert log.backtrace.size.positive? @@ -302,34 +291,35 @@ class MeasureTest < Minitest::Test it "log when the block performs a return" do assert_equal "Good", function_with_return(appender) - assert log = log_message + assert log = appender.events.first assert_equal "hello world", log.message end end describe ":silence" do + let(:appender) { SemanticLogger::Test::CaptureLogEvents.new(level: nil) } + it "silences messages" do - SemanticLogger.default_level = :info appender.measure_info("hello world", silence: :error) do appender.warn "don't log me" end - assert log = log_message + assert_equal 1, appender.events.count, -> { appender.events.to_h.ai } + assert log = appender.events.first assert_equal "hello world", log.message + assert_equal :info, log.level end it "does not silence higher level messages" do - SemanticLogger.default_level = :info - first = nil + first = nil appender.measure_info("hello world", silence: :trace) do appender.debug("hello world", payload) { "Calculations" } - first = log_message + first = appender.events.first end assert_equal "hello world -- Calculations", first.message assert_equal payload, first.payload - SemanticLogger.flush - assert log = appender.message + assert log = appender.events.last assert_equal "hello world", log.message end end diff --git a/test/metric/new_relic_test.rb b/test/metric/new_relic_test.rb index 83bbf954..dd8cd615 100644 --- a/test/metric/new_relic_test.rb +++ b/test/metric/new_relic_test.rb @@ -6,15 +6,13 @@ module Metric class NewRelicTest < Minitest::Test describe SemanticLogger::Appender::NewRelic do - before do - @appender = SemanticLogger::Metric::NewRelic.new - @message = "AppenderNewRelicTest log message" - end + let(:appender) { SemanticLogger::Metric::NewRelic.new } + let(:amessage) { "AppenderNewRelicTest log message" } it "logs counter metric" do name = amount = nil NewRelic::Agent.stub(:increment_metric, ->(name_, amount_) { name = name_, amount = amount_ }) do - @appender.info(message: @message, metric: "User/authenticated") + appender.info(message: amessage, metric: "User/authenticated") end assert_equal "Custom/User/authenticated", name.first assert_equal 1, amount @@ -23,7 +21,7 @@ class NewRelicTest < Minitest::Test it "logs duration metric" do name = duration = nil NewRelic::Agent.stub(:record_metric, ->(name_, duration_) { name = name_, duration = duration_ }) do - @appender.measure_info(message: @message, metric: "User/authenticate") do + appender.measure_info(message: amessage, metric: "User/authenticate") do sleep 0.001 end end diff --git a/test/metric/signalfx_test.rb b/test/metric/signalfx_test.rb index a2f9df6d..e9db5272 100644 --- a/test/metric/signalfx_test.rb +++ b/test/metric/signalfx_test.rb @@ -40,7 +40,7 @@ class SignalfxTest < Minitest::Test it "send custom counter metric when there is no duration" do log.metric = "Filter/count" - log.dimensions = { action: "hit", user: "jbloggs", state: "FL" } + log.dimensions = {action: "hit", user: "jbloggs", state: "FL"} assert response end @@ -50,7 +50,7 @@ class SignalfxTest < Minitest::Test end it "whitelists dimensions" do - log.named_tags = { user_id: 47, application: "sample", tracking_number: 7474, session_id: "hsdhngsd" } + log.named_tags = {user_id: 47, application: "sample", tracking_number: 7474, session_id: "hsdhngsd"} appender.formatter.dimensions = %i[user_id application] assert response end @@ -69,7 +69,7 @@ class SignalfxTest < Minitest::Test it "logs metric only metric with dimensions" do log.metric = "Filter/count" - log.dimensions = { action: "hit", user: "jbloggs", state: "FL" } + log.dimensions = {action: "hit", user: "jbloggs", state: "FL"} assert appender.should_log?(log) end end diff --git a/test/semantic_logger_logging_test.rb b/test/semantic_logger_logging_test.rb new file mode 100644 index 00000000..53cf504d --- /dev/null +++ b/test/semantic_logger_logging_test.rb @@ -0,0 +1,816 @@ +require_relative "test_helper" + +# API tests for SemanticLogger +class SemanticLoggerLoggingTest < Minitest::Test + describe SemanticLogger do + let(:logger) { SemanticLogger["TestLogger"] } + + SemanticLogger::LEVELS.each_with_index do |level, level_index| + describe "##{level}" do + describe "positional arguments logs" do + it "message only" do + events = semantic_logger_events do + logger.send(level, "hello world") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "combines message from block" do + events = semantic_logger_events do + logger.send(level, "hello world") { "Calculations" } + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world -- Calculations", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with implied payload" do + events = semantic_logger_events do + logger.send(level, "hello world", user_id: 1234) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "implied payload only" do + events = semantic_logger_events do + logger.send(level, user_id: 1234) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with implied payload and duration" do + events = semantic_logger_events do + logger.send(level, "hello world", user_id: 1234, duration: 20.3) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.3, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with explicit payload" do + events = semantic_logger_events do + logger.send(level, "hello world", payload: {user_id: 1234}) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "explicit payload only" do + events = semantic_logger_events do + logger.send(level, payload: {user_id: 1234}) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message and payload from block" do + events = semantic_logger_events do + logger.send(level) do + {message: "hello world", payload: {user_id: 123}} + end + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 123}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "payload from block" do + events = semantic_logger_events do + logger.send(level) do + {"test_key1" => "hello world", "test_key2" => "value2"} + end + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: {"test_key1" => "hello world", "test_key2" => "value2"}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message from hash does not modify hash" do + details = {message: "hello world"} + events = semantic_logger_events do + logger.send(level, details) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + assert_equal "hello world", details[:message] + end + + it "message and explicit payload from hash does not modify hash" do + details = {message: "hello world", payload: {user_id: 1230}} + events = semantic_logger_events do + logger.send(level, details) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1230}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + assert_equal "hello world", details[:message] + end + + it "message and implied payload from hash does not modify hash" do + details = {message: "hello world", user_id: 1230} + events = semantic_logger_events do + logger.send(level, details) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1230}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + assert_equal "hello world", details[:message] + assert_equal 1230, details[:user_id] + end + + it "message with explicit payload and duration" do + events = semantic_logger_events do + logger.send(level, "hello world", payload: {user_id: 1234}, duration: 20.7) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.7, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "explicit payload and metric only" do + events = semantic_logger_events do + logger.send(level, payload: {user_id: 1234}, metric: "sidekiq.job.failed") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.job.failed", + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with metric" do + events = semantic_logger_events do + logger.send(level, "hello world", metric: "sidekiq.job.failed") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.job.failed", + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "metric only" do + events = semantic_logger_events do + logger.send(level, metric: "sidekiq.job.failed") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.job.failed", + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with metric and metric_amount" do + events = semantic_logger_events do + logger.send(level, "hello world", metric: "sidekiq.queue.latency", metric_amount: 2.5) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.queue.latency", + metric_amount: 2.5, + dimensions: :nil, + time: Time + ) + end + + it "message with implied duration" do + events = semantic_logger_events do + logger.send("measure_#{level}".to_sym, "hello world") { sleep 0.1 } + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: Numeric, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with explicit duration" do + events = semantic_logger_events do + logger.send(level, "hello world", duration: 20.3) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.3, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with backtrace" do + SemanticLogger.stub(:backtrace_level_index, 0) do + events = semantic_logger_events do + logger.send(level, "hello world", request_id: 1234) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: {request_id: 1234}, + exception: :nil, + backtrace: Array, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + assert events.first.backtrace.size.positive?, events.first.backtrace + end + end + + it "message with exception" do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, "hello world", exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "exception only" do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with backtrace and exception" do + SemanticLogger.stub(:backtrace_level_index, 0) do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, "hello world", exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + assert events.first.backtrace + assert events.first.backtrace.size.positive?, events.first.backtrace + end + end + + it "does not log when below min_duration" do + events = semantic_logger_events do + logger.send(level, "hello world", min_duration: 200, duration: 123.45, payload: {tracking_number: "123456", even: 2, more: "data"}) + end + + assert events.empty? + end + end + + describe "message as keyword argument" do + it "message only" do + events = semantic_logger_events do + logger.send(level, message: "hello world") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "combines message from block" do + events = semantic_logger_events do + logger.send(level, message: "hello world") { "Calculations" } + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world -- Calculations", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with explicit payload and duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", payload: {user_id: 1234}, duration: 20.7) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.7, + payload: {user_id: 1234}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with backtrace and exception" do + SemanticLogger.stub(:backtrace_level_index, 0) do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, message: "hello world", exception: exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + assert events.first.backtrace + assert events.first.backtrace.size.positive?, events.first.backtrace + end + end + + it "does not log when below min_duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", min_duration: 200, duration: 123.45, payload: {tracking_number: "123456", even: 2, more: "data"}) + end + + assert events.empty? + end + + it "logs above min_duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", min_duration: 100, duration: 123.45, tracking_number: "123456", even: 2, more: "data") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 123.45, + payload: {tracking_number: "123456", even: 2, more: "data"}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "logs at min_duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", min_duration: 100, duration: 100.0, payload: {tracking_number: "123456", even: 2, more: "data"}) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 100.0, + payload: {tracking_number: "123456", even: 2, more: "data"}, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + end + end + end + end +end diff --git a/test/semantic_logger_test.rb b/test/semantic_logger_test.rb index 6f47d27f..361dd3f3 100644 --- a/test/semantic_logger_test.rb +++ b/test/semantic_logger_test.rb @@ -2,6 +2,8 @@ class SemanticLoggerTest < Minitest::Test describe SemanticLogger do + let(:logger) { SemanticLogger["TestLogger"] } + describe ".add_appender" do before do @appender = nil @@ -20,188 +22,226 @@ class SemanticLoggerTest < Minitest::Test end end - describe "mock_logger" do - include InMemoryAppenderHelper - - describe ".tagged" do - it "add tags to log entries" do + describe ".tagged" do + it "adds one tag" do + events = semantic_logger_events do SemanticLogger.tagged("12345", "DJHSFK") do - logger.info("Hello world") - - assert log = log_message - assert_equal %w[12345 DJHSFK], log.tags + logger.info("Hello World") end end - it "add embedded tags to log entries" do + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "Hello World", + tags: %w[12345 DJHSFK] + ) + end + + it "add embedded tags" do + events = semantic_logger_events do SemanticLogger.tagged("First Level", "tags") do SemanticLogger.tagged("Second Level") do - logger.info("Hello world") - - assert log = log_message - assert_equal ["First Level", "tags", "Second Level"], log.tags + logger.info("Hello World") end - assert_equal 2, SemanticLogger.tags.count, SemanticLogger.tags - assert_equal "First Level", SemanticLogger.tags.first - assert_equal "tags", SemanticLogger.tags.last end end - it "also supports named tagging" do + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "Hello World", + tags: ["First Level", "tags", "Second Level"] + ) + end + + it "adds named tags" do + events = semantic_logger_events do SemanticLogger.tagged(level1: 1) do assert_equal({level1: 1}, SemanticLogger.named_tags) SemanticLogger.tagged(level2: 2, more: "data") do assert_equal({level1: 1, level2: 2, more: "data"}, SemanticLogger.named_tags) SemanticLogger.tagged(level3: 3) do assert_equal({level1: 1, level2: 2, more: "data", level3: 3}, SemanticLogger.named_tags) + logger.info("Hello World") end end end end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "Hello World", + named_tags: {level1: 1, level2: 2, more: "data", level3: 3} + ) end + end - describe ".named_tags" do - it "returns named tags in creation order" do - SemanticLogger.named_tagged(level1: 1) do - assert_equal({level1: 1}, SemanticLogger.named_tags) - SemanticLogger.named_tagged(level2: 2, more: "data") do - assert_equal({level1: 1, level2: 2, more: "data"}, SemanticLogger.named_tags) - SemanticLogger.named_tagged(level3: 3) do - assert_equal({level1: 1, level2: 2, more: "data", level3: 3}, SemanticLogger.named_tags) - end + describe ".named_tags" do + it "named tags in creation order" do + SemanticLogger.named_tagged(level1: 1) do + assert_equal({level1: 1}, SemanticLogger.named_tags) + SemanticLogger.named_tagged(level2: 2, more: "data") do + assert_equal({level1: 1, level2: 2, more: "data"}, SemanticLogger.named_tags) + SemanticLogger.named_tagged(level3: 3) do + assert_equal({level1: 1, level2: 2, more: "data", level3: 3}, SemanticLogger.named_tags) end end end end + end - describe ".named_tagged" do - it "logs named tags in creation order" do + describe ".named_tagged" do + it "logs named tags in creation order" do + events = semantic_logger_events do SemanticLogger.named_tagged(level1: 1) do SemanticLogger.named_tagged(level2: 2, more: "data") do SemanticLogger.named_tagged(level3: 3) do - logger.info("Hello world") - - assert log = log_message - assert_equal({level1: 1, level2: 2, more: "data", level3: 3}, log.named_tags) + logger.info("Hello World") end end end end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "Hello World", + named_tags: {level1: 1, level2: 2, more: "data", level3: 3} + ) end + end - describe ".fast_tag" do - it "add string tag to log entries" do + describe ".fast_tag" do + it "add string tag to log entries" do + events = semantic_logger_events do logger.fast_tag("12345") do - logger.info("Hello world") - - assert log = log_message - assert_equal %w[12345], log.tags + logger.info("Hello World") end end - end - - describe ".default_level" do - before do - SemanticLogger.default_level = :debug - end - - it "not log at a level below the global default" do - assert_equal :debug, SemanticLogger.default_level - assert_equal :debug, logger.level - logger.trace("hello world") - - refute log_message - end - it "log at the instance level" do - assert_equal :debug, SemanticLogger.default_level - logger.level = :trace - assert_equal :trace, logger.level - logger.trace("hello world") + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "Hello World", + tags: %w[12345] + ) + end + end - assert log = log_message - assert_equal :trace, log.level - assert_equal "hello world", log.message + describe ".default_level" do + it "uses global default log level" do + # Uses global default level since logger does not have one set + SemanticLogger.stub(:default_level, :warn) do + assert_equal logger.level, :warn end + end - it "not log at a level below the instance level" do - assert_equal :debug, SemanticLogger.default_level - logger.level = :warn - assert_equal :warn, logger.level - logger.debug("hello world") - - refute log_message + it "logger retains explicit log level" do + # Retains the explicit log level even when global log level is different + logger.level = :trace + SemanticLogger.stub(:default_level, :warn) do + assert_equal logger.level, :trace end end + end - describe ".silence" do - before do - SemanticLogger.default_level = :info + describe ".silence" do + it "not log at a level below the default silence level" do + events = semantic_logger_events(silence: false) do + SemanticLogger.stub(:default_level, :info) do + SemanticLogger.silence do + logger.fatal("fatal") + logger.error("error") + logger.warn("warn") + logger.info("info") + logger.debug("debug") + logger.trace("trace") + end + end end + assert_equal %w[fatal error], events.map(&:message) + end - it "not log at a level below the silence level" do - assert_equal :info, SemanticLogger.default_level - assert_equal :info, logger.level - logger.silence do - logger.warn("hello world") - logger.info("hello world") - logger.debug("hello world") - logger.trace("hello world") + it "not log at a level below a specific silence level" do + events = semantic_logger_events(silence: false) do + SemanticLogger.stub(:default_level, :info) do + SemanticLogger.silence(:info) do + logger.fatal("fatal") + logger.error("error") + logger.warn("warn") + logger.info("info") + logger.debug("debug") + logger.trace("trace") + end end - - refute log_message end + assert_equal %w[fatal error warn info], events.map(&:message) + end - it "log at the instance level even with the silencer at a higher level" do - logger.level = :trace - assert_equal :trace, logger.level - logger.silence do - logger.trace("hello world") + # it "default silence level is :error, so should log everything else" do + it "silencer is ignored when logger has an explicit log level" do + logger.level = :trace + events = semantic_logger_events(silence: false) do + SemanticLogger.silence(:debug) do + logger.fatal("fatal") + logger.error("error") + logger.warn("warn") + logger.info("info") + logger.debug("debug") + logger.trace("trace") end - - assert log = log_message - assert_equal :trace, log.level - assert_equal "hello world", log.message end - it "log at a silence level below the default level" do - assert_equal :info, SemanticLogger.default_level - assert_equal :info, logger.level - logger.silence(:debug) do - logger.debug("hello world") - end + assert_equal %w[fatal error warn info debug trace], events.map(&:message) + end - assert log = log_message - assert_equal :debug, log.level - assert_equal "hello world", log.message + it "log at a silence level below the default level" do + events = semantic_logger_events(silence: false) do + SemanticLogger.stub(:default_level, :info) do + assert_equal :info, logger.level + logger.silence(:debug) do + logger.debug("hello world") + end + end end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "hello world", + level: :debug + ) end + end - describe ".on_log" do - before do - SemanticLogger.default_level = :info - end + describe ".on_log" do + after do + # Clear on_log subscribers + SemanticLogger::Logger.subscribers.clear + end - after do - SemanticLogger::Logger.subscribers.clear + it "registers a log listener" do + SemanticLogger.on_log do |log| + log.set_context(:custom_info, "test") end - it "registers a log listener" do - SemanticLogger.on_log do |log| - log.set_context(:custom_info, "test") - end - - assert_equal :info, SemanticLogger.default_level - assert_equal :info, logger.level - logger.silence(:debug) do - logger.debug("hello world") + events = semantic_logger_events do + SemanticLogger.stub(:default_level, :info) do + assert_equal :info, logger.level + SemanticLogger.silence(:debug) do + logger.debug("hello world") + end end - - assert log = log_message - assert_equal :debug, log.level - assert_equal "hello world", log.message - assert_equal "test", log.context[:custom_info] end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + message: "hello world", + context: {custom_info: "test"} + ) end end end diff --git a/test/subscriber_test.rb b/test/subscriber_test.rb index ef09ab9b..8a2fd9be 100644 --- a/test/subscriber_test.rb +++ b/test/subscriber_test.rb @@ -16,37 +16,32 @@ def log(log) let(:appender) { SimpleSubscriber.new } let(:hash_value) { {session_id: "HSSKLEU@JDK767", tracking_number: 12_345} } let(:hash_str) { hash_value.inspect.sub("{", '\\{').sub("}", '\\}') } - let(:thread_name) { Thread.current.name } - - before do - SemanticLogger.default_level = :trace - SemanticLogger.backtrace_level = :error - end + let(:file_name_reg_exp) { ' subscriber_test.rb:\d+' } describe "format logs into text form" do it "handle no message or payload" do appender.debug - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber\n/, appender.message) end it "handle message" do appender.debug "hello world" - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- hello world\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- hello world\n/, appender.message) end it "handle message and payload" do appender.debug "hello world", hash_value - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str}\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str}\n/, appender.message) end it "handle message, payload, and exception" do appender.debug "hello world", hash_value, StandardError.new("StandardError") - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str} -- Exception: StandardError: StandardError\n\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str} -- Exception: StandardError: StandardError\n\n/, appender.message) end it "logs exception with nil backtrace" do appender.debug StandardError.new("StandardError") - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- Exception: StandardError: StandardError\n\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- Exception: StandardError: StandardError\n\n/, appender.message) end it "handle nested exception" do @@ -59,7 +54,7 @@ def log(log) appender.debug e end end - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name} subscriber_test.rb:\d+\] SubscriberTest::SimpleSubscriber -- Exception: StandardError: SecondError\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- Exception: StandardError: SecondError\n/, appender.message) assert_match(/^Cause: StandardError: FirstError\n/, appender.message) if Exception.instance_methods.include?(:cause) end @@ -67,7 +62,7 @@ def log(log) exc = StandardError.new("StandardError") exc.set_backtrace([]) appender.debug exc - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- Exception: StandardError: StandardError\n\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ D \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- Exception: StandardError: StandardError\n\n/, appender.message) end it "ignores metric only messages" do @@ -87,14 +82,14 @@ def log(log) it "log #{level} with file_name" do SemanticLogger.stub(:backtrace_level_index, 0) do appender.send(level, "hello world", hash_value) - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ \w \[\d+:#{thread_name} subscriber_test.rb:\d+\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str}\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ \w \[\d+:\w+#{file_name_reg_exp}\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str}\n/, appender.message) end end it "log #{level} without file_name" do SemanticLogger.stub(:backtrace_level_index, 100) do appender.send(level, "hello world", hash_value) - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ \w \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str}\n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ \w \[\d+:\w+\] SubscriberTest::SimpleSubscriber -- hello world -- #{hash_str}\n/, appender.message) end end end @@ -121,7 +116,7 @@ def log(log) it "format using formatter" do appender.debug - assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ DEBUG \[\d+:#{thread_name}\] SubscriberTest::SimpleSubscriber -- \n/, appender.message) + assert_match(/\d+-\d+-\d+ \d+:\d+:\d+.\d+ DEBUG \[\d+:\w+\] SubscriberTest::SimpleSubscriber -- \n/, appender.message) end end diff --git a/test/test/capture_log_events_test.rb b/test/test/capture_log_events_test.rb index 71568af6..2ab60b0c 100644 --- a/test/test/capture_log_events_test.rb +++ b/test/test/capture_log_events_test.rb @@ -37,7 +37,7 @@ def disable! end it "clears the events array when clear is called" do - capture_logger.info 'a message' + capture_logger.info "a message" assert_equal(1, capture_logger.events.size) capture_logger.clear assert_equal(0, capture_logger.events.size) diff --git a/test/test_helper.rb b/test/test_helper.rb index db334010..b63fae91 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -18,6 +18,9 @@ require_relative "in_memory_appender_helper" require "amazing_print" +# Add Semantic Logger helpers for Minitest +Minitest::Test.include SemanticLogger::Test::Minitest + # Minitest::Reporters.use! Minitest::Reporters::SpecReporter.new class Minitest::Test # Use AwesomePrint to display diffs @@ -33,6 +36,16 @@ def message(msg = nil, ending = nil) end end +SemanticLogger.default_level = :trace +SemanticLogger.backtrace_level = :trace +SemanticLogger.add_appender(file_name: "test.log", formatter: :color) + +reporters = [ + Minitest::Reporters::ProgressReporter.new, + SemanticLogger::Reporters::Minitest.new +] +Minitest::Reporters.use!(reporters) + def add_mocks_to_load_path $LOAD_PATH.unshift File.join(File.dirname(__FILE__), "mocks") end