From e83e088e70b8daf22935b1c4b0368edd28014ee4 Mon Sep 17 00:00:00 2001 From: James Ebentier Date: Tue, 2 Jul 2019 10:35:30 -0700 Subject: [PATCH 1/3] No-Jira: deep merge contexts --- lib/contextual_logger.rb | 5 +++-- spec/lib/contextual_logger_spec.rb | 30 +++++++++++++++++++++++++++++- 2 files changed, 32 insertions(+), 3 deletions(-) diff --git a/lib/contextual_logger.rb b/lib/contextual_logger.rb index 5cd3dc2..8e5fc3a 100644 --- a/lib/contextual_logger.rb +++ b/lib/contextual_logger.rb @@ -1,5 +1,6 @@ # frozen_string_literal: true +require 'active_support' require 'json' require_relative './contextual_logger/context/handler' @@ -13,7 +14,7 @@ def global_context=(context) end def with_context(context) - context_handler = ContextualLogger::Context::Handler.new(current_context_for_thread.merge(context)) + context_handler = ContextualLogger::Context::Handler.new(current_context_for_thread.deep_merge(context)) context_handler.set! if block_given? yield @@ -76,7 +77,7 @@ def add(severity, message = nil, progname = nil, extra_context = nil) progname = @progname end end - write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.merge(extra_context || {})) + write_entry_to_log(severity, Time.now, progname, message, current_context_for_thread.deep_merge(extra_context || {})) true end diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 4fe83f4..715203b 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -5,9 +5,12 @@ require 'contextual_logger' describe 'ContextualLogging' do - before do + before(:each) do Time.now_override = Time.now @logger = ContextualLogger.new(Logger.new('/dev/null')) + end + + after(:each) do @logger.global_context = {} end @@ -300,4 +303,29 @@ end end end + + describe 'with varying levels of context' do + it 'deep merges contexts with sub hashes' do + expected_log_line = { + service: 'test_service', + array_context: [3], + hash_context: { + apple: 'orange', + hello: 'goodbye', + pizza: 'bagel', + }, + message: 'this is a test', + severity: 'INFO', + timestamp: Time.now, + progname: nil + }.to_json + + expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + + @logger.global_context = { service: 'test_service', array_context: [1, 2] } + @logger.with_context(hash_context: { apple: 'orange', hello: 'world' }) do + expect(@logger.info('this is a test', array_context: [3], hash_context: { pizza: 'bagel', hello: 'goodbye' })).to eq(true) + end + end + end end From 9044ee0476289ab4e76132caa566dd7e2f3fc4b7 Mon Sep 17 00:00:00 2001 From: James Ebentier Date: Tue, 2 Jul 2019 11:06:21 -0700 Subject: [PATCH 2/3] No-Jira: refactor test file to utilize rspec --- spec/lib/contextual_logger_spec.rb | 320 ++++++++++------------------- 1 file changed, 106 insertions(+), 214 deletions(-) diff --git a/spec/lib/contextual_logger_spec.rb b/spec/lib/contextual_logger_spec.rb index 715203b..170b767 100644 --- a/spec/lib/contextual_logger_spec.rb +++ b/spec/lib/contextual_logger_spec.rb @@ -3,310 +3,200 @@ require 'spec_helper' require 'logger' require 'contextual_logger' +require 'json' -describe 'ContextualLogging' do - before(:each) do - Time.now_override = Time.now - @logger = ContextualLogger.new(Logger.new('/dev/null')) - end - - after(:each) do - @logger.global_context = {} - end - - it 'should respond to with_context' do - expect(@logger).to respond_to(:with_context) - end +def expect_log_line_to_be_written(log_line) + expect_any_instance_of(Logger::LogDevice).to receive(:write).with(a_json_log_line_like("#{log_line}\n")) +end - it 'should respond to debug' do - expect(@logger).to respond_to(:debug) - end +RSpec::Matchers.define :a_json_log_line_like do |expected| + match { |actual| JSON.parse(actual) == JSON.parse(expected) } +end - it 'should respond to info' do - expect(@logger).to respond_to(:info) - end +describe 'ContextualLogging' do + before(:each) { Time.now_override = Time.now } + after(:each) { logger.global_context = {} } - it 'should respond to warn' do - expect(@logger).to respond_to(:warn) - end + subject(:logger) { ContextualLogger.new(Logger.new('/dev/null')) } - it 'should respond to error' do - expect(@logger).to respond_to(:error) - end - - it 'should respond to fatal' do - expect(@logger).to respond_to(:fatal) - end + 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) } describe 'inline context' do - it 'should print out context passed into debug' do - expected_log_line = { + let(:expected_log_hash) do + { service: 'test_service', message: 'this is a test', - severity: 'DEBUG', timestamp: Time.now, progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - expect(@logger.debug('this is a test', service: 'test_service')).to eq(true) + } end - it 'should print out context passed into info' do - expected_log_line = { - service: 'test_service', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - expect(@logger.info('this is a test', service: 'test_service')).to eq(true) + it 'prints out context passed into debug' do + expect_log_line_to_be_written(expected_log_hash.merge(severity: 'DEBUG').to_json) + expect(logger.debug('this is a test', service: 'test_service')).to eq(true) end - it 'should print out context passed into warn' do - expected_log_line = { - service: 'test_service', - message: 'this is a test', - severity: 'WARN', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - expect(@logger.warn('this is a test', service: 'test_service')).to eq(true) + it 'prints out context passed into info' do + expect_log_line_to_be_written(expected_log_hash.merge(severity: 'INFO').to_json) + expect(logger.info('this is a test', service: 'test_service')).to eq(true) end - it 'should print out context passed into error' do - expected_log_line = { - service: 'test_service', - message: 'this is a test', - severity: 'ERROR', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - expect(@logger.error('this is a test', service: 'test_service')).to eq(true) + it 'prints out context passed into warn' do + expect_log_line_to_be_written(expected_log_hash.merge(severity: 'WARN').to_json) + expect(logger.warn('this is a test', service: 'test_service')).to eq(true) end - it 'should print out context passed into fatal' do - expected_log_line = { - service: 'test_service', - message: 'this is a test', - severity: 'FATAL', - timestamp: Time.now, - progname: nil - }.to_json + it 'prints out context passed into error' do + expect_log_line_to_be_written(expected_log_hash.merge(severity: 'ERROR').to_json) + expect(logger.error('this is a test', service: 'test_service')).to eq(true) + end - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - expect(@logger.fatal('this is a test', service: 'test_service')).to eq(true) + it 'prints out context passed into fatal' do + expect_log_line_to_be_written(expected_log_hash.merge(severity: 'FATAL').to_json) + expect(logger.fatal('this is a test', service: 'test_service')).to eq(true) end end describe 'with_context block' do - it 'should print out the wrapper context when logging' do - expected_log_line = { + let(:expected_log_hash) do + { service: 'test_service', message: 'this is a test', severity: 'INFO', timestamp: Time.now, progname: nil - }.to_json + } + end - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'prints out the wrapper context when logging' do + expect_log_line_to_be_written(expected_log_hash.to_json) - @logger.with_context(service: 'test_service') do - expect(@logger.info('this is a test')).to eq(true) + logger.with_context(service: 'test_service') do + expect(logger.info('this is a test')).to eq(true) end end - it 'should merge inline context into wrapper context when logging' do - expected_log_line = { - service: 'test_service', - file: 'this_file.json', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'merges inline context into wrapper context when logging' do + expect_log_line_to_be_written(expected_log_hash.merge(file: 'this_file.json').to_json) - @logger.with_context(service: 'test_service') do - expect(@logger.info('this is a test', file: 'this_file.json')).to eq(true) + logger.with_context(service: 'test_service') do + expect(logger.info('this is a test', file: 'this_file.json')).to eq(true) end end - it 'should take inline context over wrapper context when logging' do - expected_log_line = { - service: 'test_service_2', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'takes inline context over wrapper context when logging' do + expect_log_line_to_be_written(expected_log_hash.merge(service: 'test_service_2').to_json) - @logger.with_context(service: 'test_service') do - expect(@logger.info('this is a test', service: 'test_service_2')).to eq(true) + logger.with_context(service: 'test_service') do + expect(logger.info('this is a test', service: 'test_service_2')).to eq(true) end end - it 'should combine tiered contexts when logging' do - expected_log_line = { - service: 'test_service', - file: 'this_file.json', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'combines tiered contexts when logging' do + expect_log_line_to_be_written(expected_log_hash.merge(file: 'this_file.json', service: 'test_service').to_json) - @logger.with_context(service: 'test_service') do - @logger.with_context(file: 'this_file.json') do - expect(@logger.info('this is a test')).to eq(true) + logger.with_context(service: 'test_service') do + logger.with_context(file: 'this_file.json') do + expect(logger.info('this is a test')).to eq(true) end end end it 'returns the output of the block passed in' do - expect(@logger.with_context(service: 'test_service') { 6 }).to eq(6) + expect(logger.with_context(service: 'test_service') { 6 }).to eq(6) end end describe 'with_context without block' do - it 'returns a context handler' do - expect(@logger.with_context(service: 'test_service')).to be_a(ContextualLogger::Context::Handler) - end - - it 'prints out the wrapper context with logging' do - expected_log_line = { + let(:expected_log_hash) do + { service: 'test_service', message: 'this is a test', severity: 'INFO', timestamp: Time.now, progname: nil - }.to_json + } + end - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'returns a context handler' do + expect(logger.with_context(service: 'test_service')).to be_a(ContextualLogger::Context::Handler) + end - handler = @logger.with_context(service: 'test_service') - expect(@logger.info('this is a test')).to eq(true) + it 'prints out the wrapper context with logging' do + expect_log_line_to_be_written(expected_log_hash.to_json) + + handler = logger.with_context(service: 'test_service') + expect(logger.info('this is a test')).to eq(true) handler.reset! end it 'merges inline context into wrapper context when logging' do - expected_log_line = { - service: 'test_service', - file: 'this_file.json', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json + expect_log_line_to_be_written(expected_log_hash.merge(file: 'this_file.json').to_json) - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - - handler = @logger.with_context(service: 'test_service') - expect(@logger.info('this is a test', file: 'this_file.json')).to eq(true) + handler = logger.with_context(service: 'test_service') + expect(logger.info('this is a test', file: 'this_file.json')).to eq(true) handler.reset! end it 'takes inline context over wrapper context when logging' do - expected_log_line = { - service: 'test_service_2', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + expect_log_line_to_be_written(expected_log_hash.merge(service: 'test_service_2').to_json) - handler = @logger.with_context(service: 'test_service') - expect(@logger.info('this is a test', service: 'test_service_2')).to eq(true) + handler = logger.with_context(service: 'test_service') + expect(logger.info('this is a test', service: 'test_service_2')).to eq(true) handler.reset! end it 'combines tiered contexts when logging' do - expected_log_line = { - service: 'test_service', - file: 'this_file.json', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json + expect_log_line_to_be_written(expected_log_hash.merge(file: 'this_file.json', service: 'test_service').to_json) - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - - handler1 = @logger.with_context(service: 'test_service') - @logger.with_context(file: 'this_file.json') - expect(@logger.info('this is a test')).to eq(true) + handler1 = logger.with_context(service: 'test_service') + logger.with_context(file: 'this_file.json') + expect(logger.info('this is a test')).to eq(true) handler1.reset! end end describe 'global_context' do - before do - @logger.global_context = { service: 'test_service' } - end - - it 'should print out global context with log line' do - expected_log_line = { + let(:expected_log_hash) do + { service: 'test_service', message: 'this is a test', severity: 'INFO', timestamp: Time.now, progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - - expect(@logger.info('this is a test')).to eq(true) + } end - it 'should merge global context with inline context' do - expected_log_line = { - service: 'test_service', - file: 'this_file.json', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json - - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") - - expect(@logger.info('this is a test', file: 'this_file.json')).to eq(true) + before do + logger.global_context = { service: 'test_service' } end - it 'should merge global context with with_context block' do - expected_log_line = { - service: 'test_service', - file: 'this_file.json', - message: 'this is a test', - severity: 'INFO', - timestamp: Time.now, - progname: nil - }.to_json + it 'prints out global context with log line' do + expect_log_line_to_be_written(expected_log_hash.to_json) + expect(logger.info('this is a test')).to eq(true) + end - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'merges global context with inline context' do + expect_log_line_to_be_written(expected_log_hash.merge(file: 'this_file.json').to_json) + expect(logger.info('this is a test', file: 'this_file.json')).to eq(true) + end - @logger.with_context(file: 'this_file.json') do - expect(@logger.info('this is a test')).to eq(true) + it 'merges global context with with_context block' do + expect_log_line_to_be_written(expected_log_hash.merge(file: 'this_file.json').to_json) + logger.with_context(file: 'this_file.json') do + expect(logger.info('this is a test')).to eq(true) end end end describe 'with varying levels of context' do - it 'deep merges contexts with sub hashes' do - expected_log_line = { + let(:expected_log_hash) do + { service: 'test_service', array_context: [3], hash_context: { @@ -318,13 +208,15 @@ severity: 'INFO', timestamp: Time.now, progname: nil - }.to_json + } + end - expect_any_instance_of(Logger::LogDevice).to receive(:write).with("#{expected_log_line}\n") + it 'deep merges contexts with sub hashes' do + expect_log_line_to_be_written(expected_log_hash.to_json) - @logger.global_context = { service: 'test_service', array_context: [1, 2] } - @logger.with_context(hash_context: { apple: 'orange', hello: 'world' }) do - expect(@logger.info('this is a test', array_context: [3], hash_context: { pizza: 'bagel', hello: 'goodbye' })).to eq(true) + logger.global_context = { service: 'test_service', array_context: [1, 2] } + logger.with_context(hash_context: { apple: 'orange', hello: 'world' }) do + expect(logger.info('this is a test', array_context: [3], hash_context: { pizza: 'bagel', hello: 'goodbye' })).to eq(true) end end end From 2a88f07ba930614a782bcec6f79fcb0c19ea10a4 Mon Sep 17 00:00:00 2001 From: James Ebentier Date: Wed, 3 Jul 2019 14:03:41 -0700 Subject: [PATCH 3/3] No-Jira: add active support to run time dependencies for the gem --- Gemfile.lock | 1 + contextual_logger.gemspec | 1 + 2 files changed, 2 insertions(+) diff --git a/Gemfile.lock b/Gemfile.lock index 74f5fb2..c80b972 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -2,6 +2,7 @@ PATH remote: . specs: contextual_logger (0.3.0) + activesupport json GEM diff --git a/contextual_logger.gemspec b/contextual_logger.gemspec index fe24e2c..28ebd24 100644 --- a/contextual_logger.gemspec +++ b/contextual_logger.gemspec @@ -14,4 +14,5 @@ Gem::Specification.new do |spec| spec.metadata = { 'source_code_uri' => 'https://github.com/Invoca/contextual_logger' } spec.add_runtime_dependency 'json' + spec.add_runtime_dependency 'activesupport' end