From 559af35603bde522e548a097388c48199d6a5569 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Sun, 19 Jan 2020 10:03:41 -0800 Subject: [PATCH 01/27] no-jira: remove redundant namespace prefix --- lib/contextual_logger.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 8e5fc3a..d5166a8 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -10,11 +10,11 @@ def self.new(logger) end def global_context=(context) - ContextualLogger::Context::Handler.new(context).set! + 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 = Context::Handler.new(current_context_for_thread.deep_merge(context)) context_handler.set! if block_given? yield @@ -26,7 +26,7 @@ def with_context(context) end def current_context_for_thread - ContextualLogger::Context::Handler.current_context + Context::Handler.current_context end def format_message(severity, timestamp, progname, message, context) From 31fb5f90daea76a9a727d49eb40c36897b02ea10 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Sun, 19 Jan 2020 10:54:23 -0800 Subject: [PATCH 02/27] no-jira: add missing tests for log_level; split add from add_if_enabled --- lib/contextual_logger.rb | 28 ++++++---- spec/lib/contextual_logger_spec.rb | 88 ++++++++++++++++++++++++++++-- 2 files changed, 99 insertions(+), 17 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index d5166a8..245e7a1 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -40,34 +40,41 @@ def format_message(severity, timestamp, progname, message, context) end def debug(progname = nil, **extra_context, &block) - add(Logger::Severity::DEBUG, nil, progname, extra_context, &block) + add_if_enabled(Logger::Severity::DEBUG, nil, progname, extra_context, &block) end def info(progname = nil, **extra_context, &block) - add(Logger::Severity::INFO, nil, progname, extra_context, &block) + add_if_enabled(Logger::Severity::INFO, nil, progname, extra_context, &block) end def warn(progname = nil, **extra_context, &block) - add(Logger::Severity::WARN, nil, progname, extra_context, &block) + add_if_enabled(Logger::Severity::WARN, nil, progname, extra_context, &block) end def error(progname = nil, **extra_context, &block) - add(Logger::Severity::ERROR, nil, progname, extra_context, &block) + add_if_enabled(Logger::Severity::ERROR, nil, progname, extra_context, &block) end def fatal(progname = nil, **extra_context, &block) - add(Logger::Severity::FATAL, nil, progname, extra_context, &block) + add_if_enabled(Logger::Severity::FATAL, nil, progname, extra_context, &block) end def unknown(progname = nil, **extra_context, &block) - add(Logger::Severity::UNKNOWN, nil, progname, extra_context, &block) + add_if_enabled(Logger::Severity::UNKNOWN, nil, progname, extra_context, &block) end - def add(severity, message = nil, progname = nil, extra_context = nil) - severity ||= UNKNOWN - if @logdev.nil? || (severity < @level) - return true + def log_level_enabled(severity) + severity >= @level + end + + def add_if_enabled(severity, message, progname, extra_context, &block) + if @logdev && log_level_enabled(severity) + add(severity, message, progname, extra_context, &block) end + true + end + + def add(severity, message, progname, extra_context) progname ||= @progname if message.nil? if block_given? @@ -78,7 +85,6 @@ def add(severity, message = nil, progname = nil, extra_context = nil) 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) diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 170b767..99089ea 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -13,18 +13,94 @@ 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)) } + + 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 + + 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 From 6734bc73086bb0f46e2370748a1e3762e31615d1 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 20 Jan 2020 13:18:20 -0800 Subject: [PATCH 03/27] no-jira: make explicit LoggerMixin so the ContextualLogger namespace isn't overloaded --- lib/contextual_logger.rb | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 245e7a1..8194276 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -5,10 +5,13 @@ 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 + module LoggerMixin def global_context=(context) Context::Handler.new(context).set! end @@ -19,7 +22,7 @@ def with_context(context) if block_given? yield else - context_handler + context_handler # JEB, is this actually useful? The set! and reset! wouldn't mean anything, so it would just be calling Context::Handler.new, right? -Colin end ensure context_handler.reset! if block_given? From 04b49456f4fcfb55bd5155208648d05661543b0e Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 20 Jan 2020 13:22:59 -0800 Subject: [PATCH 04/27] no-jira: make add_if_enabled to separate out log_level_enabled? from add --- lib/contextual_logger.rb | 68 ++++++++++++++++++---------------------- 1 file changed, 30 insertions(+), 38 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 8194276..df10d30 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -32,70 +32,61 @@ 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) - - if @formatter - @formatter.call(severity, timestamp, progname, message_with_context) - else - "#{message_with_context.to_json}\n" - end - end - - def debug(progname = nil, **extra_context, &block) - add_if_enabled(Logger::Severity::DEBUG, nil, progname, extra_context, &block) + def debug(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::DEBUG, message || yield, extra_context: extra_context) end - def info(progname = nil, **extra_context, &block) - add_if_enabled(Logger::Severity::INFO, nil, progname, extra_context, &block) + def info(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::INFO, message || yield, extra_context: extra_context) end - def warn(progname = nil, **extra_context, &block) - add_if_enabled(Logger::Severity::WARN, nil, progname, extra_context, &block) + def warn(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::WARN, message || yield, extra_context: extra_context) end - def error(progname = nil, **extra_context, &block) - add_if_enabled(Logger::Severity::ERROR, nil, progname, extra_context, &block) + def error(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::ERROR, message || yield, extra_context: extra_context) end - def fatal(progname = nil, **extra_context, &block) - add_if_enabled(Logger::Severity::FATAL, nil, progname, extra_context, &block) + def fatal(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::FATAL, message || yield, extra_context: extra_context) end - def unknown(progname = nil, **extra_context, &block) - add_if_enabled(Logger::Severity::UNKNOWN, nil, progname, extra_context, &block) + def unknown(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::UNKNOWN, message || yield, extra_context: extra_context) end - def log_level_enabled(severity) + def log_level_enabled?(severity) severity >= @level end - def add_if_enabled(severity, message, progname, extra_context, &block) - if @logdev && log_level_enabled(severity) - add(severity, message, progname, extra_context, &block) + def add_if_enabled(severity, message, extra_context:) + if @logdev && log_level_enabled?(severity) + add(severity, message: message, progname: @progname, extra_context: extra_context) end true end - def add(severity, message, progname, extra_context) - progname ||= @progname - if message.nil? - if block_given? - message = yield - else - message = progname - progname = @progname - end + def add(severity, message:, progname:, extra_context:) + write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context)) + end + + private + + def format_message(severity, timestamp, progname, message, context) + message_with_context = message_with_context(context, message, severity, timestamp, progname) + + if @formatter + @formatter.call(severity, timestamp, progname, message_with_context) + else + "#{message_with_context.to_json}\n" end - write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context || {})) 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_with_context(context, message, severity, timestamp, progname) context.merge( message: message, @@ -104,4 +95,5 @@ def message_with_context(context, message, severity, timestamp, progname) progname: progname ) end + end end From 0b3ada9b1c65d7d9154eaabbda302677eeec1cdb Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 20 Jan 2020 13:23:30 -0800 Subject: [PATCH 05/27] no-jira: omit progname: when it's null --- lib/contextual_logger.rb | 15 +++++++++------ spec/lib/contextual_logger_spec.rb | 15 +++++---------- .../mixins/active_support_tagged_logging_spec.rb | 1 - 3 files changed, 14 insertions(+), 17 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index df10d30..0d1d8dd 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -88,12 +88,15 @@ def write_entry_to_log(severity, timestamp, progname, message, context) end def message_with_context(context, message, severity, timestamp, progname) - context.merge( - message: message, - severity: severity, - timestamp: timestamp, - progname: progname - ) + extra_context = + { + message: message, + severity: severity, + timestamp: timestamp + } + extra_context[:progname] = progname if progname + + context.merge(extra_context) end end end diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 99089ea..1d8ac7e 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -107,8 +107,7 @@ def log_message_levels { service: 'test_service', message: 'this is a test', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -144,8 +143,7 @@ def log_message_levels service: 'test_service', message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -194,8 +192,7 @@ def log_message_levels service: 'test_service', message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -243,8 +240,7 @@ def log_message_levels service: 'test_service', message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end @@ -282,8 +278,7 @@ def log_message_levels }, message: 'this is a test', severity: 'INFO', - timestamp: Time.now, - progname: nil + timestamp: Time.now } end diff --git a/spec/lib/mixins/active_support_tagged_logging_spec.rb b/spec/lib/mixins/active_support_tagged_logging_spec.rb index ced2273..d51ad45 100644 --- a/spec/lib/mixins/active_support_tagged_logging_spec.rb +++ b/spec/lib/mixins/active_support_tagged_logging_spec.rb @@ -21,7 +21,6 @@ message: 'this is a test', severity: 'DEBUG', timestamp: Time.now, - progname: nil, log_tags: 'test' }.to_json From e51d702f53cb708509e93a8b963f5b6c5a50fcea Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 17 Feb 2020 16:16:29 -0800 Subject: [PATCH 06/27] no-jira: move logdev check into write_entry_to_log and make it public --- lib/contextual_logger.rb | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 0d1d8dd..102c014 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -61,7 +61,7 @@ def log_level_enabled?(severity) end def add_if_enabled(severity, message, extra_context:) - if @logdev && log_level_enabled?(severity) + if log_level_enabled?(severity) add(severity, message: message, progname: @progname, extra_context: extra_context) end true @@ -71,6 +71,10 @@ def add(severity, message:, progname:, extra_context:) write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context)) 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 format_message(severity, timestamp, progname, message, context) @@ -83,10 +87,6 @@ def format_message(severity, timestamp, progname, message, context) end end - def write_entry_to_log(severity, timestamp, progname, message, context) - @logdev.write(format_message(format_severity(severity), timestamp, progname, message, context)) - end - def message_with_context(context, message, severity, timestamp, progname) extra_context = { From 099cd6843232223201de19e0416d34503da495a6 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 17 Feb 2020 16:21:42 -0800 Subject: [PATCH 07/27] no-jira: add LoggerWithContext and its spec --- lib/contextual_logger/logger_with_context.rb | 33 +++++++ .../logger_with_context_spec.rb | 86 +++++++++++++++++++ 2 files changed, 119 insertions(+) create mode 100644 lib/contextual_logger/logger_with_context.rb create mode 100644 spec/lib/contextual_logger/logger_with_context_spec.rb diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb new file mode 100644 index 0000000..e8db0f3 --- /dev/null +++ b/lib/contextual_logger/logger_with_context.rb @@ -0,0 +1,33 @@ +# 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 that may be set independently of the logger it delegates to (the latter's log level is ignored). + class LoggerWithContext + include LoggerMixin + + attr_accessor :level + attr_reader :context + + def initialize(logger, context, level: nil) + @logger = logger + @level = level || logger.level + @context = context + @merged_context_cache = {} # so we don't have to merge every time + end + + def write_entry_to_log(severity, timestamp, progname, message, context) + if @merged_context_cache.size > 5000 # keep this cache memory use finite + @merged_context_cache = {} + end + merged_context = @merged_context_cache[context] ||= @context.deep_merge(context) + @logger.write_entry_to_log(severity, timestamp, progname, message, merged_context) + end + + class << self + def for_log_source(logger, log_source) + new(logger, log_source: log_source) + end + end + end +end 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..a80acc7 --- /dev/null +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -0,0 +1,86 @@ +# 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 'log_level' do + 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 + + 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 include('{"log_source":"redis_client","message":"fatal message","severity":"FATAL",') + end + + it "merges context" do + subject.fatal("fatal message", call_id: "234-123") + expect(log_stream.string).to include('{"log_source":"redis_client","call_id":"234-123","message":"fatal message","severity":"FATAL",') + end + + it "allows context to be overridden" do + subject.fatal("fatal message", log_source: "frontend") + expect(log_stream.string).to include('{"log_source":"frontend","message":"fatal message","severity":"FATAL",') + 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 "ignores changes to the base log level" do + subject + base_logger.level = Logger::Severity::INFO + log_at_every_level(subject) + expect(log_message_levels).to eq(["fatal", "unknown"]) + end + + it "can change its own log_level" do + subject.level = Logger::Severity::INFO + log_at_every_level(subject) + expect(log_message_levels).to eq(["info", "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" do + log_at_every_level(subject) + expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) + end + 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 include('{"log_source":"frontend","message":"fatal message","severity":"FATAL",') + end + end + end + end +end From 2e10bb63bc905e5cddf7aba1b7bcbd64773bd5ce Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 17 Feb 2020 16:24:58 -0800 Subject: [PATCH 08/27] no-jira: DRY up Helpers --- .../logger_with_context_spec.rb | 13 ------------- spec/lib/contextual_logger_spec.rb | 13 ------------- spec/spec_helper.rb | 17 +++++++++++++++++ 3 files changed, 17 insertions(+), 26 deletions(-) diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index a80acc7..b241544 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -8,19 +8,6 @@ describe ContextualLogger::LoggerWithContext do context 'log_level' do - 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 - 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)) } diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 1d8ac7e..837d8e6 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -27,19 +27,6 @@ def expect_log_line_to_be_written(log_line) let(:log_level) { Logger::Severity::DEBUG } let(:logger) { ContextualLogger.new(Logger.new(log_stream, level: log_level)) } - 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 - context 'at default level' do it 'respects log level debug' do log_at_every_level(default_logger) 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 From 7f8d2be3ba0e7b9a852eaf0852f20302d1324414 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 17 Feb 2020 21:16:30 -0800 Subject: [PATCH 09/27] no-jira: add test for cache clearing at 5000 entries --- lib/contextual_logger/logger_with_context.rb | 2 +- .../contextual_logger/logger_with_context_spec.rb | 15 +++++++++++++++ 2 files changed, 16 insertions(+), 1 deletion(-) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index e8db0f3..145c8bb 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -17,7 +17,7 @@ def initialize(logger, context, level: nil) end def write_entry_to_log(severity, timestamp, progname, message, context) - if @merged_context_cache.size > 5000 # keep this cache memory use finite + if @merged_context_cache.size >= 5000 # keep this cache memory use finite @merged_context_cache = {} end merged_context = @merged_context_cache[context] ||= @context.deep_merge(context) diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index b241544..ab9e6bf 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -30,6 +30,21 @@ expect(log_stream.string).to include('{"log_source":"frontend","message":"fatal message","severity":"FATAL",') end + context "context caching" do + it "caches contexts to avoid merging over and over" 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"} ]) + 4998.times do |i| + subject.fatal("fatal message", log_source: "gem #{i}") + end + expect(subject.instance_variable_get(:@merged_context_cache).size).to eq(5000) + subject.fatal("fatal message", log_source: "gem 5000") + expect(subject.instance_variable_get(:@merged_context_cache).size).to eq(1) + end + end + context "log level changes" do it "defaults to the base log level" do expect(subject.level).to eq(Logger::Severity::FATAL) From 24df4fb33646e1882baacc27bdc9212adb342457 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 17 Feb 2020 21:18:28 -0800 Subject: [PATCH 10/27] no-jira: add spaces before braces --- spec/lib/contextual_logger/logger_with_context_spec.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index ab9e6bf..efdb3f7 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -33,9 +33,9 @@ context "context caching" do it "caches contexts to avoid merging over and over" do subject.fatal("fatal message", log_source: "frontend") - expect(subject.instance_variable_get(:@merged_context_cache).keys).to eq([{ 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"} ]) + expect(subject.instance_variable_get(:@merged_context_cache).keys).to eq([{ log_source: "frontend" }, { log_source: "redis_client" }]) 4998.times do |i| subject.fatal("fatal message", log_source: "gem #{i}") end From 06266f393f3bb7fb216c9d86ee1fc4226d4e0bca Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 18 Feb 2020 12:29:02 -0800 Subject: [PATCH 11/27] no-jira: move spec/{context,mixins} down under contextual_logger/ to match source --- spec/lib/{ => contextual_logger}/context/handler_spec.rb | 0 .../mixins/active_support_tagged_logging_spec.rb | 0 2 files changed, 0 insertions(+), 0 deletions(-) rename spec/lib/{ => contextual_logger}/context/handler_spec.rb (100%) rename spec/lib/{ => contextual_logger}/mixins/active_support_tagged_logging_spec.rb (100%) 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/mixins/active_support_tagged_logging_spec.rb b/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb similarity index 100% rename from spec/lib/mixins/active_support_tagged_logging_spec.rb rename to spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb From a6400d50987e62719f5dcbc33a2ad68a4dcbdac0 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 18 Feb 2020 12:52:53 -0800 Subject: [PATCH 12/27] no-jira: change override_level to allow nil (the default) and then delegate to logger for level --- lib/contextual_logger.rb | 2 +- lib/contextual_logger/logger_with_context.rb | 16 +++++++++++---- .../logger_with_context_spec.rb | 20 +++++++++++++++---- 3 files changed, 29 insertions(+), 9 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 102c014..74b6abf 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -57,7 +57,7 @@ def unknown(message = nil, extra_context = {}) end def log_level_enabled?(severity) - severity >= @level + severity >= level end def add_if_enabled(severity, message, extra_context:) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index 145c8bb..45724ef 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -2,20 +2,28 @@ module ContextualLogger # A logger that deep_merges additional context and then delegates to the given logger. - # Keeps it own log level that may be set independently of the logger it delegates to (the latter's log level is ignored). + # 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_accessor :level - attr_reader :context + attr_reader :logger, :override_level, :context def initialize(logger, context, level: nil) @logger = logger - @level = level || logger.level + @override_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 = override_level + end + def write_entry_to_log(severity, timestamp, progname, message, context) if @merged_context_cache.size >= 5000 # keep this cache memory use finite @merged_context_cache = {} diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index efdb3f7..a77b858 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -52,23 +52,35 @@ expect(log_message_levels).to eq(["fatal", "unknown"]) end - it "ignores changes to the base log level" do + 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(["fatal", "unknown"]) + expect(log_message_levels).to eq(["info", "warn", "error", "fatal", "unknown"]) end - it "can change its own log_level" do + 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" do + 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 From 25c9cb425240533eca81513ce9613186950dbfa7 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 18 Feb 2020 12:54:24 -0800 Subject: [PATCH 13/27] no-jira: indent LoggerMixin --- lib/contextual_logger.rb | 132 +++++++++++++++++++-------------------- 1 file changed, 66 insertions(+), 66 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 74b6abf..ec12849 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -12,91 +12,91 @@ def new(logger) end module LoggerMixin - def global_context=(context) - Context::Handler.new(context).set! - end + def global_context=(context) + Context::Handler.new(context).set! + end - def with_context(context) - context_handler = Context::Handler.new(current_context_for_thread.deep_merge(context)) - context_handler.set! - if block_given? - yield - else - context_handler # JEB, is this actually useful? The set! and reset! wouldn't mean anything, so it would just be calling Context::Handler.new, right? -Colin + def with_context(context) + context_handler = Context::Handler.new(current_context_for_thread.deep_merge(context)) + context_handler.set! + if block_given? + yield + else + context_handler # JEB, is this actually useful? The set! and reset! wouldn't mean anything, so it would just be calling Context::Handler.new, right? -Colin + end + ensure + context_handler.reset! if block_given? end - ensure - context_handler.reset! if block_given? - end - def current_context_for_thread - Context::Handler.current_context - end + def current_context_for_thread + Context::Handler.current_context + end - def debug(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::DEBUG, message || yield, extra_context: extra_context) - end + def debug(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::DEBUG, message || yield, extra_context: extra_context) + end - def info(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::INFO, message || yield, extra_context: extra_context) - end + def info(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::INFO, message || yield, extra_context: extra_context) + end - def warn(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::WARN, message || yield, extra_context: extra_context) - end + def warn(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::WARN, message || yield, extra_context: extra_context) + end - def error(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::ERROR, message || yield, extra_context: extra_context) - end + def error(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::ERROR, message || yield, extra_context: extra_context) + end - def fatal(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::FATAL, message || yield, extra_context: extra_context) - end + def fatal(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::FATAL, message || yield, extra_context: extra_context) + end - def unknown(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::UNKNOWN, message || yield, extra_context: extra_context) - end + def unknown(message = nil, extra_context = {}) + add_if_enabled(Logger::Severity::UNKNOWN, message || yield, extra_context: extra_context) + end - def log_level_enabled?(severity) - severity >= level - end + def log_level_enabled?(severity) + severity >= level + end - def add_if_enabled(severity, message, extra_context:) - if log_level_enabled?(severity) - add(severity, message: message, progname: @progname, extra_context: extra_context) + def add_if_enabled(severity, message, extra_context:) + if log_level_enabled?(severity) + add(severity, message: message, progname: @progname, extra_context: extra_context) + end + true end - true - end - def add(severity, message:, progname:, extra_context:) - write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context)) - end + def add(severity, message:, progname:, extra_context:) + write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context)) + end - def write_entry_to_log(severity, timestamp, progname, message, context) - @logdev&.write(format_message(format_severity(severity), timestamp, progname, message, context)) - end + def write_entry_to_log(severity, timestamp, progname, message, context) + @logdev&.write(format_message(format_severity(severity), timestamp, progname, message, context)) + end - private + private - def format_message(severity, timestamp, progname, message, context) - message_with_context = message_with_context(context, message, severity, timestamp, progname) + def format_message(severity, timestamp, progname, message, context) + message_with_context = message_with_context(context, message, severity, timestamp, progname) - if @formatter - @formatter.call(severity, timestamp, progname, message_with_context) - else - "#{message_with_context.to_json}\n" + if @formatter + @formatter.call(severity, timestamp, progname, message_with_context) + else + "#{message_with_context.to_json}\n" + end end - end - def message_with_context(context, message, severity, timestamp, progname) - extra_context = - { - message: message, - severity: severity, - timestamp: timestamp - } - extra_context[:progname] = progname if progname + def message_with_context(context, message, severity, timestamp, progname) + extra_context = + { + message: message, + severity: severity, + timestamp: timestamp + } + extra_context[:progname] = progname if progname - context.merge(extra_context) - end + context.merge(extra_context) + end end end From 90388c444df94fa4e8b2a3c88db2299d45d97289 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 18 Feb 2020 12:58:17 -0800 Subject: [PATCH 14/27] no-jira: clarify the with_context contract and unify the block_given? logic --- lib/contextual_logger.rb | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index ec12849..9463eff 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -20,12 +20,15 @@ def with_context(context) context_handler = Context::Handler.new(current_context_for_thread.deep_merge(context)) context_handler.set! if block_given? - yield + begin + yield + ensure + context_handler.reset! + end else - context_handler # JEB, is this actually useful? The set! and reset! wouldn't mean anything, so it would just be calling Context::Handler.new, right? -Colin + # If no block given, the context handler is returned to the caller so they can handle reset! themselves. + context_handler end - ensure - context_handler.reset! if block_given? end def current_context_for_thread From 902a561889e518b902e47fdbf3ddf93546711fd1 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 24 Feb 2020 10:42:03 -0800 Subject: [PATCH 15/27] no-jira: restore add signature since Rails calls it --- lib/contextual_logger.rb | 48 ++++++++++++++---------------- spec/lib/contextual_logger_spec.rb | 20 +++++++++++++ 2 files changed, 42 insertions(+), 26 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 9463eff..e5c5dd3 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -35,63 +35,59 @@ def current_context_for_thread Context::Handler.current_context end - def debug(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::DEBUG, message || yield, extra_context: extra_context) + def debug(message = nil, context = {}) + add_if_enabled(Logger::Severity::DEBUG, message || yield, context: context) end - def info(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::INFO, message || yield, extra_context: extra_context) + def info(message = nil, context = {}) + add_if_enabled(Logger::Severity::INFO, message || yield, context: context) end - def warn(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::WARN, message || yield, extra_context: extra_context) + def warn(message = nil, context = {}) + add_if_enabled(Logger::Severity::WARN, message || yield, context: context) end - def error(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::ERROR, message || yield, extra_context: extra_context) + def error(message = nil, context = {}) + add_if_enabled(Logger::Severity::ERROR, message || yield, context: context) end - def fatal(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::FATAL, message || yield, extra_context: extra_context) + def fatal(message = nil, context = {}) + add_if_enabled(Logger::Severity::FATAL, message || yield, context: context) end - def unknown(message = nil, extra_context = {}) - add_if_enabled(Logger::Severity::UNKNOWN, message || yield, extra_context: extra_context) + def unknown(message = nil, context = {}) + add_if_enabled(Logger::Severity::UNKNOWN, message || yield, context: context) end def log_level_enabled?(severity) severity >= level end - def add_if_enabled(severity, message, extra_context:) + def add_if_enabled(severity, message, context:) if log_level_enabled?(severity) - add(severity, message: message, progname: @progname, extra_context: extra_context) + write_entry_to_log(severity, Time.now, @progname, message, context: current_context_for_thread.deep_merge(context)) end true end - def add(severity, message:, progname:, extra_context:) - write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context)) - end - - def write_entry_to_log(severity, timestamp, progname, message, context) - @logdev&.write(format_message(format_severity(severity), timestamp, progname, message, context)) + def write_entry_to_log(severity, timestamp, progname, message, context:) + @logdev&.write(format_message(format_severity(severity), timestamp, progname, message, context: context)) end private - def format_message(severity, timestamp, progname, message, context) - message_with_context = message_with_context(context, message, severity, timestamp, progname) + def format_message(severity, timestamp, progname, message, context: {}) + message_with_context_hash = message_with_context(context, message, severity, timestamp, progname) if @formatter - @formatter.call(severity, timestamp, progname, message_with_context) + @formatter.call(severity, timestamp, progname, message_with_context_hash) else - "#{message_with_context.to_json}\n" + "#{message_with_context_hash.to_json}\n" end end - def message_with_context(context, message, severity, timestamp, progname) - extra_context = + def message_with_context(extra_context, message, severity, timestamp, progname) + context = { message: message, severity: severity, diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 837d8e6..f096a7e 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -278,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 From 857996098beec1153bbbfa971038538cfbcd767d Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 24 Feb 2020 13:51:30 -0800 Subject: [PATCH 16/27] no-jira: fix to use context: kwarg --- lib/contextual_logger/logger_with_context.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index 45724ef..1e3cf82 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -24,12 +24,12 @@ def level=(override_level) @override_level = override_level end - def write_entry_to_log(severity, timestamp, progname, message, context) + def write_entry_to_log(severity, timestamp, progname, message, context:) if @merged_context_cache.size >= 5000 # keep this cache memory use finite @merged_context_cache = {} end merged_context = @merged_context_cache[context] ||= @context.deep_merge(context) - @logger.write_entry_to_log(severity, timestamp, progname, message, merged_context) + @logger.write_entry_to_log(severity, timestamp, progname, message, context: merged_context) end class << self From d15922ec002f5692a30d14612e786ad34bb673b4 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 24 Feb 2020 13:51:53 -0800 Subject: [PATCH 17/27] no-jira: fix tests to tolerate different JSON key order --- spec/lib/contextual_logger/logger_with_context_spec.rb | 8 ++++---- .../mixins/active_support_tagged_logging_spec.rb | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index a77b858..291e754 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -17,17 +17,17 @@ it "adds context" do subject.fatal("fatal message") - expect(log_stream.string).to include('{"log_source":"redis_client","message":"fatal message","severity":"FATAL",') + 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 include('{"log_source":"redis_client","call_id":"234-123","message":"fatal message","severity":"FATAL",') + 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 include('{"log_source":"frontend","message":"fatal message","severity":"FATAL",') + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"frontend"\}/) end context "context caching" do @@ -92,7 +92,7 @@ it "creates a new logger_with_context using that log_source" do subject.fatal("fatal message") - expect(log_stream.string).to include('{"log_source":"frontend","message":"fatal message","severity":"FATAL",') + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"frontend"\}/) end end end diff --git a/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb b/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb index d51ad45..e5c0a7d 100644 --- a/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb +++ b/spec/lib/contextual_logger/mixins/active_support_tagged_logging_spec.rb @@ -17,10 +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, + service: 'test_service', log_tags: 'test' }.to_json From dad998249f5390c300bf6757a44e02497eee1e5e Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 24 Feb 2020 15:04:57 -0800 Subject: [PATCH 18/27] no-jira: cap the merge cache at 1000; beyond that, still read, but don't write --- lib/contextual_logger/logger_with_context.rb | 11 +++++++---- .../lib/contextual_logger/logger_with_context_spec.rb | 10 +++++----- 2 files changed, 12 insertions(+), 9 deletions(-) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index 1e3cf82..0f17cd7 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -25,10 +25,13 @@ def level=(override_level) end def write_entry_to_log(severity, timestamp, progname, message, context:) - if @merged_context_cache.size >= 5000 # keep this cache memory use finite - @merged_context_cache = {} - end - merged_context = @merged_context_cache[context] ||= @context.deep_merge(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 diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index 291e754..6a9a4ce 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -31,17 +31,17 @@ end context "context caching" do - it "caches contexts to avoid merging over and over" 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" }]) - 4998.times do |i| + 998.times do |i| subject.fatal("fatal message", log_source: "gem #{i}") end - expect(subject.instance_variable_get(:@merged_context_cache).size).to eq(5000) - subject.fatal("fatal message", log_source: "gem 5000") - expect(subject.instance_variable_get(:@merged_context_cache).size).to eq(1) + 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 From 13bd8dde878f1ad493de93d5b440d39af981d4b2 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Mon, 24 Feb 2020 15:31:37 -0800 Subject: [PATCH 19/27] no-jira: remove unused context; ArgumentError if logger doesn't have LoggerMixin --- lib/contextual_logger/logger_with_context.rb | 1 + .../logger_with_context_spec.rb | 140 +++++++++--------- 2 files changed, 74 insertions(+), 67 deletions(-) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index 0f17cd7..056a71a 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -10,6 +10,7 @@ class LoggerWithContext 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 @override_level = level @context = context diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index 6a9a4ce..bf687b6 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -7,93 +7,99 @@ require 'json' describe ContextualLogger::LoggerWithContext do - context 'log_level' 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" } } + 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) } + 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 "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 "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 - it "allows context to be overridden" do + 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(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","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 "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 + 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 - 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 "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 "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) + 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(["info", "warn", "error", "fatal", "unknown"]) + expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) log_stream.string.clear - subject.level = nil - expect(subject.override_level).to eq(nil) + base_logger.level = Logger::Severity::FATAL log_at_every_level(subject) expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) end + end + 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 "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") } + 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" do + subject.fatal("fatal message") + expect(log_stream.string).to match(/\{"message":"fatal message","severity":"FATAL","timestamp":".*","log_source":"frontend"\}/) end end end From 3defc3672eea63185528a5ba647c2363f08482e8 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 25 Feb 2020 08:49:48 -0800 Subject: [PATCH 20/27] no-jira: rename to message_hash_with_context; normalize arg order; don't mutate context --- lib/contextual_logger.rb | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index e5c5dd3..6702f08 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -77,25 +77,25 @@ def write_entry_to_log(severity, timestamp, progname, message, context:) private def format_message(severity, timestamp, progname, message, context: {}) - message_with_context_hash = message_with_context(context, message, severity, timestamp, progname) + message_hash = message_hash_with_context(severity, timestamp, progname, message, context: context) if @formatter - @formatter.call(severity, timestamp, progname, message_with_context_hash) + @formatter.call(severity, timestamp, progname, message_hash) else - "#{message_with_context_hash.to_json}\n" + "#{message_hash.to_json}\n" end end - def message_with_context(extra_context, message, severity, timestamp, progname) - context = + def message_hash_with_context(severity, timestamp, progname, message, context:) + message_hash = { - message: message, - severity: severity, + message: message, + severity: severity, timestamp: timestamp } - extra_context[:progname] = progname if progname + message_hash[:progname] = progname if progname - context.merge(extra_context) + message_hash.merge!(context) end end end From 90b130142a2f886b30cb7847df0f170b40b1b5d9 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 25 Feb 2020 10:08:42 -0800 Subject: [PATCH 21/27] no-jira: plumb level: through for_log_source --- lib/contextual_logger/logger_with_context.rb | 4 ++-- spec/lib/contextual_logger/logger_with_context_spec.rb | 8 ++++++++ 2 files changed, 10 insertions(+), 2 deletions(-) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index 056a71a..f14a633 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -37,8 +37,8 @@ def write_entry_to_log(severity, timestamp, progname, message, context:) end class << self - def for_log_source(logger, log_source) - new(logger, log_source: log_source) + def for_log_source(logger, log_source, level: nil) + new(logger, { log_source: log_source }, level: level) end end end diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index bf687b6..df62a07 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -101,6 +101,14 @@ 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 From fe17c6de54c73ebf210418dcd4be1dc1c8454854 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 25 Feb 2020 10:18:36 -0800 Subject: [PATCH 22/27] no-jira: bump version to 0.4.pre.1 --- Gemfile.lock | 4 ++-- contextual_logger.gemspec | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/Gemfile.lock b/Gemfile.lock index e5adf82..e315723 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - contextual_logger (0.3.1) + contextual_logger (0.4.pre.1) activesupport json @@ -97,4 +97,4 @@ DEPENDENCIES ruby-prof-flamegraph BUNDLED WITH - 1.16.4 + 1.17.3 diff --git a/contextual_logger.gemspec b/contextual_logger.gemspec index b567164..879b892 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.1' spec.license = 'MIT' spec.date = '2018-10-12' spec.summary = 'Add context to your logger' From 469dea0c0d06b2129232e1048223652860e50d17 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 25 Feb 2020 10:29:33 -0800 Subject: [PATCH 23/27] no-jira: add Rakefile and rake --- Gemfile | 1 + Gemfile.lock | 2 ++ Rakefile | 14 ++++++++++++++ 3 files changed, 17 insertions(+) create mode 100644 Rakefile 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 e315723..6cdbdbd 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -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) 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 From 84c5da9b9eccc6d6aab0af360988118aa0b42887 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Tue, 25 Feb 2020 10:33:48 -0800 Subject: [PATCH 24/27] no-jira: add allowed_push_host --- contextual_logger.gemspec | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/contextual_logger.gemspec b/contextual_logger.gemspec index 879b892..57edb3a 100644 --- a/contextual_logger.gemspec +++ b/contextual_logger.gemspec @@ -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' From 86ed9d594c40f0e152e12e3c046225590514a672 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Wed, 26 Feb 2020 20:47:39 -0800 Subject: [PATCH 25/27] allow string log levels --- lib/contextual_logger/logger_with_context.rb | 24 +++++++++++++++++-- .../logger_with_context_spec.rb | 13 ++++++++++ 2 files changed, 35 insertions(+), 2 deletions(-) diff --git a/lib/contextual_logger/logger_with_context.rb b/lib/contextual_logger/logger_with_context.rb index f14a633..467100e 100644 --- a/lib/contextual_logger/logger_with_context.rb +++ b/lib/contextual_logger/logger_with_context.rb @@ -12,7 +12,7 @@ class LoggerWithContext def initialize(logger, context, level: nil) logger.is_a?(LoggerMixin) or raise ArgumentError, "logger must include ContextualLogger::LoggerMixin (got #{logger.inspect})" @logger = logger - @override_level = level + self.level = level @context = context @merged_context_cache = {} # so we don't have to merge every time end @@ -22,7 +22,27 @@ def level end def level=(override_level) - @override_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:) diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index df62a07..dca09fc 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -84,6 +84,19 @@ expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) end end + Logger + 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 From 646ad06465897c99b6a39fb8f21342df8fd3c7da Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Wed, 26 Feb 2020 20:48:17 -0800 Subject: [PATCH 26/27] bump version to 0.4.pre.2 --- Gemfile.lock | 2 +- contextual_logger.gemspec | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Gemfile.lock b/Gemfile.lock index 6cdbdbd..81012d2 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - contextual_logger (0.4.pre.1) + contextual_logger (0.4.pre.2) activesupport json diff --git a/contextual_logger.gemspec b/contextual_logger.gemspec index 57edb3a..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.4.pre.1' + spec.version = '0.4.pre.2' spec.license = 'MIT' spec.date = '2018-10-12' spec.summary = 'Add context to your logger' From 5734bd32cc0b353fce41ab7ee9b558ce580d1053 Mon Sep 17 00:00:00 2001 From: Colin Kelley Date: Thu, 27 Feb 2020 06:02:06 -0800 Subject: [PATCH 27/27] remove Logger typo --- lib/contextual_logger.rb | 1 + spec/lib/contextual_logger/logger_with_context_spec.rb | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 6702f08..31775c9 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -65,6 +65,7 @@ def log_level_enabled?(severity) 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 diff --git a/spec/lib/contextual_logger/logger_with_context_spec.rb b/spec/lib/contextual_logger/logger_with_context_spec.rb index dca09fc..b1e52c8 100644 --- a/spec/lib/contextual_logger/logger_with_context_spec.rb +++ b/spec/lib/contextual_logger/logger_with_context_spec.rb @@ -84,7 +84,7 @@ expect(log_message_levels).to eq(["warn", "error", "fatal", "unknown"]) end end - Logger + context "with string log level" do it "allows creating" do logger_with_context = ContextualLogger::LoggerWithContext.new(base_logger, context, level: 'INFO')