241 lines
6.9 KiB
Ruby
241 lines
6.9 KiB
Ruby
require 'rails_helper'
|
|
|
|
describe Dunlop::NestedLogger do
|
|
|
|
let(:time) { '2016-03-09T18:22:40Z'.to_time }
|
|
before do
|
|
Dunlop::NestedLogger.reset
|
|
Timecop.freeze time
|
|
end
|
|
after { Timecop.return }
|
|
|
|
it 'logs complex nested situation' do
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
Dunlop::NestedLogger.scope('scope 2a') do
|
|
Dunlop::NestedLogger.info('text 2')
|
|
end
|
|
Dunlop::NestedLogger.scope('scope 2b') do
|
|
Dunlop::NestedLogger.info('text 3a')
|
|
Dunlop::NestedLogger.warn('text 3b')
|
|
end
|
|
Dunlop::NestedLogger.info('text q')
|
|
Dunlop::NestedLogger.scope('scope 2b') do
|
|
Dunlop::NestedLogger.info('text 4')
|
|
end
|
|
Dunlop::NestedLogger.info('text 5')
|
|
end
|
|
|
|
Dunlop::NestedLogger.flush.should eq [{
|
|
'scope 1' => [
|
|
'INFO - text 1',
|
|
{ 'scope 2a' => ['INFO - text 2'] },
|
|
{ 'scope 2b' => ['INFO - text 3a', 'WARNING - text 3b'] },
|
|
'INFO - text q',
|
|
{ 'scope 2b' => ['INFO - text 4'] },
|
|
'INFO - text 5',
|
|
]
|
|
}]
|
|
end
|
|
|
|
it 'returns return value of block inside scope (thus is transparant)' do
|
|
value = Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
Dunlop::NestedLogger.scope('scope 2a') do
|
|
'test'
|
|
end
|
|
end
|
|
|
|
value.should eq 'test'
|
|
end
|
|
|
|
it 'is thread safe and merges intermediate loggings from other threads' do
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
threads = []
|
|
5.times do |i|
|
|
threads << Thread.new do
|
|
if [0,1,4].include? i
|
|
Dunlop::NestedLogger.scope("thread scope #{i}") do
|
|
Dunlop::NestedLogger.info("thread text #{i}")
|
|
end
|
|
elsif i == 3
|
|
Dunlop::NestedLogger.info("thread text #{i}a")
|
|
Dunlop::NestedLogger.info("thread text #{i}b")
|
|
end
|
|
end
|
|
end
|
|
threads.each { |thread| thread.join }
|
|
Dunlop::NestedLogger.merge_threads(threads)
|
|
Dunlop::NestedLogger.info('text 3')
|
|
end
|
|
|
|
Dunlop::NestedLogger.flush.should eq [{
|
|
"scope 1"=>[
|
|
"INFO - text 1",
|
|
{"thread scope 0"=>["INFO - thread text 0"]},
|
|
{"thread scope 1"=>["INFO - thread text 1"]},
|
|
"INFO - thread text 3a",
|
|
"INFO - thread text 3b",
|
|
{"thread scope 4"=>["INFO - thread text 4"]},
|
|
"INFO - text 3"
|
|
]
|
|
}]
|
|
end
|
|
|
|
it 'benchmarks' do
|
|
Timecop.freeze do
|
|
Dunlop::NestedLogger.benchmark do
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
Dunlop::NestedLogger.scope('scope 2a') do
|
|
Dunlop::NestedLogger.info('text 2')
|
|
end
|
|
Dunlop::NestedLogger.scope('scope 2b', benchmark: false) do
|
|
Dunlop::NestedLogger.info('text 2')
|
|
end
|
|
Dunlop::NestedLogger.scope('empty sandbox', benchmark: false) do
|
|
end
|
|
end
|
|
end
|
|
end
|
|
|
|
Dunlop::NestedLogger.flush_as_yaml.should eq <<-DOC
|
|
- scope 1:
|
|
- INFO - text 1
|
|
- scope 2a:
|
|
- INFO - text 2
|
|
- INFO - duration = 0.0s
|
|
- scope 2b:
|
|
- INFO - text 2
|
|
- INFO - duration = 0.0s
|
|
DOC
|
|
end
|
|
|
|
#it 'resets after flush' do
|
|
#Dunlop::NestedLogger.info('text 1')
|
|
#Dunlop::NestedLogger.flush
|
|
#Dunlop::NestedLogger.info('text 2')
|
|
#Dunlop::NestedLogger.flush.should eq ["INFO - text 2"]
|
|
#end
|
|
|
|
it 'use sandbox scope to ignore existing scope' do
|
|
flush_1 = {}
|
|
flush_2 = {}
|
|
flush_3 = {}
|
|
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1a')
|
|
Dunlop::NestedLogger.scope('sandbox scope') do
|
|
Dunlop::NestedLogger.scope('scope 2') do
|
|
Dunlop::NestedLogger.info('text 2a')
|
|
Dunlop::NestedLogger.scope('scope 3') do
|
|
Dunlop::NestedLogger.info('text 3a')
|
|
end
|
|
end
|
|
flush_3 = Dunlop::NestedLogger.flush
|
|
end
|
|
flush_2 = Dunlop::NestedLogger.flush
|
|
end
|
|
flush_1 = Dunlop::NestedLogger.flush
|
|
|
|
flush_1.should eq []
|
|
flush_2.should eq ["INFO - text 1a"]
|
|
flush_3.should eq [{"scope 2"=>["INFO - text 2a", {"scope 3"=>["INFO - text 3a"]}]}]
|
|
end
|
|
|
|
it 'removes flushed scope from existing scope' do
|
|
flush_1 = {}
|
|
flush_2 = {}
|
|
flush_3 = {}
|
|
|
|
Dunlop::NestedLogger.info('text 0a')
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1a')
|
|
Dunlop::NestedLogger.scope('scope 2') do
|
|
Dunlop::NestedLogger.info('text 2a')
|
|
end
|
|
flush_1 = Dunlop::NestedLogger.flush
|
|
Dunlop::NestedLogger.info('text 1b')
|
|
end
|
|
Dunlop::NestedLogger.info('text 0b')
|
|
flush_2 = Dunlop::NestedLogger.flush
|
|
Dunlop::NestedLogger.info('text 0c')
|
|
flush_3 = Dunlop::NestedLogger.flush
|
|
|
|
flush_1.should eq ["INFO - text 1a", {"scope 2"=>["INFO - text 2a"]}]
|
|
flush_2.should eq ["INFO - text 0a", {"scope 1"=>["INFO - text 1b"]}, "INFO - text 0b"]
|
|
flush_3.should eq ["INFO - text 0c"]
|
|
end
|
|
|
|
it 'ignores empty scopes (non top level)' do
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
Dunlop::NestedLogger.scope('scope 2') {}
|
|
Timecop.freeze do
|
|
Dunlop::NestedLogger.benchmark do
|
|
Dunlop::NestedLogger.scope('scope 3') {}
|
|
end
|
|
end
|
|
end
|
|
|
|
Dunlop::NestedLogger.flush.should eq [{"scope 1"=>["INFO - text 1", {"scope 3"=>["INFO - duration = 0.0s"]}]}]
|
|
end
|
|
|
|
it 'ignores empty scopes (top level)' do
|
|
Dunlop::NestedLogger.scope('scope 1') {}
|
|
Dunlop::NestedLogger.flush.should eq []
|
|
end
|
|
|
|
it 'merges scope stack (useful for handing over after fork)' do
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
end
|
|
stack_1 = Dunlop::NestedLogger.copy_scope_stack_for_merge
|
|
Dunlop::NestedLogger.flush.should eq [{"scope 1"=>["INFO - text 1"]}]
|
|
|
|
Dunlop::NestedLogger.scope('scope 3') do
|
|
Dunlop::NestedLogger.info('text 3')
|
|
Dunlop::NestedLogger.merge_scope_stack(stack_1)
|
|
end
|
|
|
|
Dunlop::NestedLogger.flush.should eq [{"scope 3"=>["INFO - text 3", {"scope 1"=>["INFO - text 1"]}]}]
|
|
end
|
|
|
|
it 'allows unscoped entries' do
|
|
Dunlop::NestedLogger.info('text 1')
|
|
Dunlop::NestedLogger.scope('scope 1') do
|
|
Dunlop::NestedLogger.info('text 2')
|
|
end
|
|
Dunlop::NestedLogger.warn('text 3')
|
|
Dunlop::NestedLogger.flush.should eq [
|
|
"INFO - text 1",
|
|
{"scope 1"=>["INFO - text 2"]},
|
|
"WARNING - text 3"
|
|
]
|
|
end
|
|
|
|
it 'ignores empty flush' do
|
|
expect {
|
|
Dunlop::NestedLogger.flush
|
|
Dunlop::NestedLogger.flush
|
|
}.not_to raise_error
|
|
end
|
|
|
|
context 'formatter' do
|
|
before do
|
|
Dunlop::NestedLogger.formatter = proc do |severity, datetime, progname, msg|
|
|
"#{severity} - custom - #{msg}"
|
|
end
|
|
end
|
|
after { Dunlop::NestedLogger.reset_formatter }
|
|
|
|
it 'allows custom formatter' do
|
|
Dunlop::NestedLogger.info 'test'
|
|
Dunlop::NestedLogger.flush.should eq ['info - custom - test']
|
|
end
|
|
end
|
|
|
|
end
|
|
|