diff --git a/Gemfile b/Gemfile index bb5794b..4bd5c46 100644 --- a/Gemfile +++ b/Gemfile @@ -10,6 +10,7 @@ group :development do gem 'activesupport' gem 'bump', '~> 0.6.1' gem 'pry' + gem 'rake' gem 'rubocop', '0.54.0' gem 'rubocop-git' gem 'ruby-prof' diff --git a/Gemfile.lock b/Gemfile.lock index e5adf82..81012d2 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - contextual_logger (0.3.1) + contextual_logger (0.4.pre.2) activesupport json @@ -38,6 +38,7 @@ GEM coderay (~> 1.1.0) method_source (~> 0.9.0) rainbow (3.0.0) + rake (13.0.1) rspec (3.8.0) rspec-core (~> 3.8.0) rspec-expectations (~> 3.8.0) @@ -89,6 +90,7 @@ DEPENDENCIES contextual_logger! coveralls pry + rake rspec rspec_junit_formatter rubocop (= 0.54.0) @@ -97,4 +99,4 @@ DEPENDENCIES ruby-prof-flamegraph BUNDLED WITH - 1.16.4 + 1.17.3 diff --git a/Rakefile b/Rakefile new file mode 100644 index 0000000..5b092c7 --- /dev/null +++ b/Rakefile @@ -0,0 +1,14 @@ +#!/usr/bin/env rake +# frozen_string_literal: true + +require "bundler/gem_tasks" +require 'rubygems' +require 'bundler/setup' + + +require 'rspec/core/rake_task' + +RSpec::Core::RakeTask.new(:spec) + +task test: :spec +task default: :spec diff --git a/contextual_logger.gemspec b/contextual_logger.gemspec index b567164..aa220f3 100644 --- a/contextual_logger.gemspec +++ b/contextual_logger.gemspec @@ -2,7 +2,7 @@ Gem::Specification.new do |spec| spec.name = 'contextual_logger' - spec.version = '0.3.1' + spec.version = '0.4.pre.2' spec.license = 'MIT' spec.date = '2018-10-12' spec.summary = 'Add context to your logger' @@ -11,7 +11,10 @@ Gem::Specification.new do |spec| spec.email = 'jebentier@invoca.com' spec.files = Dir['lib/**/*'] spec.homepage = 'https://rubygems.org/gems/contextual_logger' - spec.metadata = { 'source_code_uri' => 'https://github.com/Invoca/contextual_logger' } + spec.metadata = { + "source_code_uri" => "https://github.com/Invoca/process_settings", + "allowed_push_host" => "https://rubygems.org" + } spec.add_runtime_dependency 'json' spec.add_runtime_dependency 'activesupport' diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 8e5fc3a..31775c9 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -5,94 +5,98 @@ require_relative './contextual_logger/context/handler' module ContextualLogger - def self.new(logger) - logger.extend(self) + class << self + def new(logger) + logger.extend(LoggerMixin) + end end - def global_context=(context) - ContextualLogger::Context::Handler.new(context).set! - end + module LoggerMixin + def global_context=(context) + Context::Handler.new(context).set! + end - def with_context(context) - context_handler = ContextualLogger::Context::Handler.new(current_context_for_thread.deep_merge(context)) - context_handler.set! - if block_given? - yield - else - context_handler + def with_context(context) + context_handler = Context::Handler.new(current_context_for_thread.deep_merge(context)) + context_handler.set! + if block_given? + begin + yield + ensure + context_handler.reset! + end + else + # If no block given, the context handler is returned to the caller so they can handle reset! themselves. + context_handler + end end - ensure - context_handler.reset! if block_given? - end - def current_context_for_thread - ContextualLogger::Context::Handler.current_context - end + def current_context_for_thread + Context::Handler.current_context + end - def format_message(severity, timestamp, progname, message, context) - message_with_context = message_with_context(context, message, severity, timestamp, progname) + def debug(message = nil, context = {}) + add_if_enabled(Logger::Severity::DEBUG, message || yield, context: context) + end - if @formatter - @formatter.call(severity, timestamp, progname, message_with_context) - else - "#{message_with_context.to_json}\n" + def info(message = nil, context = {}) + add_if_enabled(Logger::Severity::INFO, message || yield, context: context) end - end - def debug(progname = nil, **extra_context, &block) - add(Logger::Severity::DEBUG, nil, progname, extra_context, &block) - end + def warn(message = nil, context = {}) + add_if_enabled(Logger::Severity::WARN, message || yield, context: context) + end - def info(progname = nil, **extra_context, &block) - add(Logger::Severity::INFO, nil, progname, extra_context, &block) - end + def error(message = nil, context = {}) + add_if_enabled(Logger::Severity::ERROR, message || yield, context: context) + end - def warn(progname = nil, **extra_context, &block) - add(Logger::Severity::WARN, nil, progname, extra_context, &block) - end + def fatal(message = nil, context = {}) + add_if_enabled(Logger::Severity::FATAL, message || yield, context: context) + end - def error(progname = nil, **extra_context, &block) - add(Logger::Severity::ERROR, nil, progname, extra_context, &block) - end + def unknown(message = nil, context = {}) + add_if_enabled(Logger::Severity::UNKNOWN, message || yield, context: context) + end - def fatal(progname = nil, **extra_context, &block) - add(Logger::Severity::FATAL, nil, progname, extra_context, &block) - end + def log_level_enabled?(severity) + severity >= level + end - def unknown(progname = nil, **extra_context, &block) - add(Logger::Severity::UNKNOWN, nil, progname, extra_context, &block) - end + def add_if_enabled(severity, message, context:) + if log_level_enabled?(severity) + @progname ||= nil + write_entry_to_log(severity, Time.now, @progname, message, context: current_context_for_thread.deep_merge(context)) + end + true + end - def add(severity, message = nil, progname = nil, extra_context = nil) - severity ||= UNKNOWN - if @logdev.nil? || (severity < @level) - return true + def write_entry_to_log(severity, timestamp, progname, message, context:) + @logdev&.write(format_message(format_severity(severity), timestamp, progname, message, context: context)) end - progname ||= @progname - if message.nil? - if block_given? - message = yield + + private + + def format_message(severity, timestamp, progname, message, context: {}) + message_hash = message_hash_with_context(severity, timestamp, progname, message, context: context) + + if @formatter + @formatter.call(severity, timestamp, progname, message_hash) else - message = progname - progname = @progname + "#{message_hash.to_json}\n" end end - write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context || {})) - true - end - - def write_entry_to_log(severity, timestamp, progname, message, context) - @logdev.write(format_message(format_severity(severity), timestamp, progname, message, context)) - end - private + def message_hash_with_context(severity, timestamp, progname, message, context:) + message_hash = + { + message: message, + severity: severity, + timestamp: timestamp + } + message_hash[:progname] = progname if progname - def message_with_context(context, message, severity, timestamp, progname) - context.merge( - message: message, - severity: severity, - timestamp: timestamp, - progname: progname - ) + message_hash.merge!(context) + end end end diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb new file mode 100644 index 0000000..467100e --- /dev/null +++ b/lib/contextual_logger/logger_with_context.rb @@ -0,0 +1,65 @@ +# frozen_string_literal: true + +module ContextualLogger + # A logger that deep_merges additional context and then delegates to the given logger. + # Keeps it own log level (called override_level) that may be set independently of the logger it delegates to. + # If override_level is non-nil, it takes precedence; if it is nil (the default), then it delegates to the logger. + class LoggerWithContext + include LoggerMixin + + attr_reader :logger, :override_level, :context + + def initialize(logger, context, level: nil) + logger.is_a?(LoggerMixin) or raise ArgumentError, "logger must include ContextualLogger::LoggerMixin (got #{logger.inspect})" + @logger = logger + self.level = level + @context = context + @merged_context_cache = {} # so we don't have to merge every time + end + + def level + @override_level || @logger.level + end + + def level=(override_level) + @override_level = + if (Logger::Severity::DEBUG..Logger::Severity::UNKNOWN).include?(override_level) || override_level.nil? + override_level + else + case override_level.to_s.downcase + when 'debug' + Logger::Severity::DEBUG + when 'info' + Logger::Severity::INFO + when 'warn' + Logger::Severity::WARN + when 'error' + Logger::Severity::ERROR + when 'fatal' + Logger::Severity::FATAL + when 'unknown' + Logger::Severity::UNKNOWN + else + raise ArgumentError, "invalid log level: #{override_level.inspect}" + end + end + end + + def write_entry_to_log(severity, timestamp, progname, message, context:) + merged_context = + if @merged_context_cache.size >= 1000 # keep this cache memory use finite + @merged_context_cache[context] || @context.deep_merge(context) + else + @merged_context_cache[context] ||= @context.deep_merge(context) + end + + @logger.write_entry_to_log(severity, timestamp, progname, message, context: merged_context) + end + + class << self + def for_log_source(logger, log_source, level: nil) + new(logger, { log_source: log_source }, level: level) + end + end + end +end diff --git a/spec/lib/context/handler_spec.rb b/spec/lib/contextual_logger/context/handler_spec.rb similarity index 100% rename from spec/lib/context/handler_spec.rb rename to spec/lib/contextual_logger/context/handler_spec.rb diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb new file mode 100644 index 0000000..b1e52c8 --- /dev/null +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -0,0 +1,127 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'logger' +require 'contextual_logger' +require 'contextual_logger/logger_with_context' +require 'json' + +describe ContextualLogger::LoggerWithContext do + context "when created with a base logger" do + let(:log_stream) { StringIO.new } + let(:base_logger) { ContextualLogger.new(Logger.new(log_stream, level: Logger::Severity::FATAL)) } + let(:context) { { log_source: "redis_client" } } + + subject(:logger_with_context) { ContextualLogger::LoggerWithContext.new(base_logger, context) } + + it "adds context" do + subject.fatal("fatal message") + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"redis_client"\}/) + end + + it "merges context" do + subject.fatal("fatal message", call_id: "234-123") + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"redis_client","call_id":"234-123"\}/) + end + + it "allows context to be overridden" do + subject.fatal("fatal message", log_source: "frontend") + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"frontend"\}/) + end + + context "context caching" do + it "caches contexts to avoid merging over and over (but caps the cache size)" do + subject.fatal("fatal message", log_source: "frontend") + expect(subject.instance_variable_get(:@merged_context_cache).keys).to eq([{ log_source: "frontend" }]) + subject.fatal("fatal message", log_source: "redis_client") + expect(subject.instance_variable_get(:@merged_context_cache).keys).to eq([{ log_source: "frontend" }, { log_source: "redis_client" }]) + 998.times do |i| + subject.fatal("fatal message", log_source: "gem #{i}") + end + expect(subject.instance_variable_get(:@merged_context_cache).size).to eq(1000) + subject.fatal("fatal message", log_source: "gem 1000") + expect(subject.instance_variable_get(:@merged_context_cache).size).to eq(1000) + end + end + + context "log level changes" do + it "defaults to the base log level" do + expect(subject.level).to eq(Logger::Severity::FATAL) + log_at_every_level(logger_with_context) + expect(log_message_levels).to eq(["fatal", "unknown"]) + end + + it "follows changes to the base log level when default level is used" do + subject + base_logger.level = Logger::Severity::INFO + log_at_every_level(subject) + expect(log_message_levels).to eq(["info", "warn", "error", "fatal", "unknown"]) + end + + it "can change its own log_level and then ignores changes to the base log level (as long as it's non-nil)" do + subject.level = Logger::Severity::INFO + base_logger.level = Logger::Severity::WARN + expect(subject.override_level).to eq(Logger::Severity::INFO) + log_at_every_level(subject) + expect(log_message_levels).to eq(["info", "warn", "error", "fatal", "unknown"]) + log_stream.string.clear + subject.level = nil + expect(subject.override_level).to eq(nil) + log_at_every_level(subject) + expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) + end + + context "when constructed with its own level" do + subject(:logger_with_context) { ContextualLogger::LoggerWithContext.new(base_logger, context, level: Logger::Severity::WARN) } + + it "respects its own log_level and ignores changes to the base log level" do + expect(subject.override_level).to eq(Logger::Severity::WARN) + log_at_every_level(subject) + expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) + log_stream.string.clear + base_logger.level = Logger::Severity::FATAL + log_at_every_level(subject) + expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) + end + end + + context "with string log level" do + it "allows creating" do + logger_with_context = ContextualLogger::LoggerWithContext.new(base_logger, context, level: 'INFO') + expect(logger_with_context.level).to eq(Logger::Severity::INFO) + end + + it "allows assignment" do + logger_with_context = ContextualLogger::LoggerWithContext.new(base_logger, context) + logger_with_context.level = 'ERROR' + expect(logger_with_context.level).to eq(Logger::Severity::ERROR) + end + end + end + + context "when base logger doesn't include LoggerMixin" do + let(:base_logger) { Object.new } + + it "raises ArgumentError" do + expect { subject }.to raise_exception(ArgumentError, /logger must include ContextualLogger::LoggerMixin \(got .*\)/) + end + end + + context "for_log_source" do + subject(:logger_with_context) { ContextualLogger::LoggerWithContext.for_log_source(base_logger, "frontend") } + + it "creates a new logger_with_context using that log_source" do + subject.fatal("fatal message") + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"frontend"\}/) + end + + it "creates a new logger_with_context using that log_source and level:" do + logger = ContextualLogger::LoggerWithContext.for_log_source(base_logger, "frontend", level: Logger::Severity::FATAL) + logger.fatal("fatal message") + logger.error("error message") + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"frontend"\}/) + expect(log_stream.string).to_not match(/error message/) + end + end + end +end diff --git a/spec/lib/mixins/active_support_tagged_logging_spec.rb b/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb similarity index 97% rename from spec/lib/mixins/active_support_tagged_logging_spec.rb rename to spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb index ced2273..e5c0a7d 100644 --- a/spec/lib/mixins/active_support_tagged_logging_spec.rb +++ b/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb @@ -17,11 +17,10 @@ it 'should log log_tags as additional context' do @logger.push_tags('test') expected_log_line = { - service: 'test_service', message: 'this is a test', severity: 'DEBUG', timestamp: Time.now, - progname: nil, + service: 'test_service', log_tags: 'test' }.to_json diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 170b767..f096a7e 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -13,26 +13,88 @@ def expect_log_line_to_be_written(log_line) match { |actual| JSON.parse(actual) == JSON.parse(expected) } end -describe 'ContextualLogging' do +describe ContextualLogger do before(:each) { Time.now_override = Time.now } after(:each) { logger.global_context = {} } subject(:logger) { ContextualLogger.new(Logger.new('/dev/null')) } it { is_expected.to respond_to(:with_context) } - it { is_expected.to respond_to(:debug) } - it { is_expected.to respond_to(:info) } - it { is_expected.to respond_to(:warn) } - it { is_expected.to respond_to(:error) } - it { is_expected.to respond_to(:fatal) } + + context 'log_level' do + let(:log_stream) { StringIO.new } + let(:default_logger) { ContextualLogger.new(Logger.new(log_stream)) } + let(:log_level) { Logger::Severity::DEBUG } + let(:logger) { ContextualLogger.new(Logger.new(log_stream, level: log_level)) } + + context 'at default level' do + it 'respects log level debug' do + log_at_every_level(default_logger) + expect(log_message_levels).to eq(["debug", "info", "warn", "error", "fatal", "unknown"]) + end + end + + context 'at level debug' do + let(:log_level) { Logger::Severity::DEBUG } + + it 'respects log level' do + log_at_every_level(logger) + expect(log_message_levels).to eq(["debug", "info", "warn", "error", "fatal", "unknown"]) + end + end + + context 'at level info' do + let(:log_level) { Logger::Severity::INFO } + + it 'respects log level' do + log_at_every_level(logger) + expect(log_message_levels).to eq(["info", "warn", "error", "fatal", "unknown"]) + end + end + + context 'at level warn' do + let(:log_level) { Logger::Severity::WARN } + + it 'respects log level' do + log_at_every_level(logger) + expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) + end + end + + context 'at level error' do + let(:log_level) { Logger::Severity::ERROR } + + it 'respects log level' do + log_at_every_level(logger) + expect(log_message_levels).to eq(["error", "fatal", "unknown"]) + end + end + + context 'at level fatal' do + let(:log_level) { Logger::Severity::FATAL } + + it 'respects log level' do + log_at_every_level(logger) + expect(log_message_levels).to eq(["fatal", "unknown"]) + end + end + + context 'at level unknown' do + let(:log_level) { Logger::Severity::UNKNOWN } + + it 'respects log level' do + log_at_every_level(logger) + expect(log_message_levels).to eq(["unknown"]) + end + end + end describe 'inline context' do let(:expected_log_hash) do { service: 'test_service', message: 'this is a test', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -68,8 +130,7 @@ def expect_log_line_to_be_written(log_line) service: 'test_service', message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -118,8 +179,7 @@ def expect_log_line_to_be_written(log_line) service: 'test_service', message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -167,8 +227,7 @@ def expect_log_line_to_be_written(log_line) service: 'test_service', message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -206,8 +265,7 @@ def expect_log_line_to_be_written(log_line) }, message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -220,4 +278,24 @@ def expect_log_line_to_be_written(log_line) end end end + + describe 'add' do + let(:log_stream) { StringIO.new } + let(:logger) { ContextualLogger.new(Logger.new(log_stream, level: Logger::Severity::DEBUG)) } + + it "preserves the Logger interface with message only" do + expect(logger.add(Logger::Severity::INFO, "info message")).to eq(true) + expect(log_stream.string).to match(/\{"message":"info message","severity":"INFO","timestamp":".*"\}/) + end + + it "preserves the Logger interface with nil message & block" do + expect(logger.add(Logger::Severity::INFO, nil) { "info message" }).to eq(true) + expect(log_stream.string).to match(/\{"message":"info message","severity":"INFO","timestamp":".*"\}/) + end + + it "preserves the Logger interface with nil message & message in progname spot" do + expect(logger.add(Logger::Severity::INFO, nil, "info message")).to eq(true) + expect(log_stream.string).to match(/\{"message":"info message","severity":"INFO","timestamp":".*"\}/) + end + end end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index cfc702c..781caa6 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -3,6 +3,21 @@ require 'coveralls' Coveralls.wear! +module Helpers + def log_at_every_level(logger) + logger.debug("debug message") + logger.info("info message") + logger.warn("warn message") + logger.error("error message") + logger.fatal("fatal message") + logger.unknown("unknown message") + end + + def log_message_levels + log_stream.string.split("\n").map { |log_line| log_line[/([a-z]+) message/, 1] } + end +end + RSpec.configure do |config| config.expect_with :rspec do |expectations| expectations.include_chain_clauses_in_custom_matcher_descriptions = true @@ -11,6 +26,8 @@ mocks.verify_partial_doubles = true end config.shared_context_metadata_behavior = :apply_to_host_groups + + config.include Helpers end class Time