Merge pull request #4 from firespring/story/TP-17814

Add a normalizer to deal with certain nested context objects dumping with different formats that cause Logstash and Loggly to complain.

lib/hedgelog.rb

@@ -2,6 +2,7 @@
 require 'hedgelog/version'
 require 'hedgelog/context'
 require 'hedgelog/scrubber'
+require 'hedgelog/normalizer'
 require 'logger'
 require 'yajl'
 
@@ -26,7 +27,8 @@ def initialize(logdev = STDOUT, shift_age = nil, shift_size = nil)
     @logdev = nil
     @app = nil
     @scrubber = Hedgelog::Scrubber.new
-    @channel_context = Hedgelog::Context.new(@scrubber)
+    @normalizer = Hedgelog::Normalizer.new
+    @channel_context = Hedgelog::Context.new(@scrubber, @normalizer)
 
     if logdev.is_a?(self.class)
       @channel = logdev
@@ -51,7 +53,7 @@ def add(severity = LEVELS[:unknown], message = nil, progname = nil, context = {}
     message, context = *yield if block
     context ||= {}
 
-    context = Hedgelog::Context.new(@scrubber, context) unless context.is_a? Hedgelog::Context
+    context = Hedgelog::Context.new(@scrubber, @normalizer, context) unless context.is_a? Hedgelog::Context
     context.merge!(@channel_context)
     context[:message] ||= message
 
@@ -119,6 +121,7 @@ def level_from_int(level)
   def write(severity, context)
     return true if @logdev.nil?
 
+    context.normalize!
     context.scrub!
 
     data = context.merge(default_data(severity))

lib/hedgelog/context.rb

@@ -1,12 +1,14 @@
 require 'hedgelog/scrubber'
+require 'hedgelog/normalizer'
 
 class Hedgelog
   class Context
-    def initialize(scrubber, data = {})
+    def initialize(scrubber, normalizer, data = {})
       raise ::ArgumentError, "#{self.class}: argument must be Hash got #{data.class}." unless data.is_a? Hash
       check_reserved_keys(data)
       @data = data
       @scrubber = scrubber
+      @normalizer = normalizer
     end
 
     def []=(key, val)
@@ -50,6 +52,11 @@ def scrub!
       self
     end
 
+    def normalize!
+      @data = @normalizer.normalize(@data)
+      self
+    end
+
     def to_h
       @data
     end

lib/hedgelog/normalizer.rb

@@ -0,0 +1,33 @@
+class Hedgelog
+  class Normalizer
+    def normalize(data)
+      # Need to Marshal.dump/Marshal.load to deep copy the input so that scrubbing doesn't change global state
+      d = Marshal.load(Marshal.dump(data))
+      normalize_hash(d)
+    end
+
+    def normalize_struct(struct)
+      normalize_hash(Hash[struct.each_pair.to_a])
+    end
+
+    def normalize_hash(hash)
+      Hash[hash.map do |key, val|
+        [key, normalize_thing(val)]
+      end]
+    end
+
+    def normalize_array(array)
+      array.to_json
+    end
+
+    private
+
+    def normalize_thing(thing)
+      return '' if thing.nil?
+      return normalize_struct(thing) if thing.is_a?(Struct)
+      return normalize_array(thing) if thing.is_a?(Array)
+      return normalize_hash(thing) if thing.is_a?(Hash)
+      thing
+    end
+  end
+end

spec/hedgelog/context_spec.rb

@@ -2,10 +2,11 @@
 require 'hedgelog/context'
 
 dummy_scrubber = Hedgelog::ScrubReplacement.new(:dummy, 'DUMMY')
+dummy_normalizer = Hedgelog::Normalizer.new
 
 describe Hedgelog::Context do
   describe '#[]=' do
-    subject(:instance) { described_class.new(dummy_scrubber, data) }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, data) }
     subject(:instance_with_value) do
       instance[key] = val
       instance
@@ -29,7 +30,7 @@
   end
 
   describe '#[]' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
 
     context 'when key is a valid key' do
       it 'sets the value on the context' do
@@ -44,7 +45,7 @@
   end
 
   describe '#delete' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
 
     context 'when key is a valid key' do
       it 'deletes the key' do
@@ -62,7 +63,7 @@
   end
 
   describe '#clear' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
     it 'clears the context' do
       expect(instance[:foo]).to eq 'bar'
       instance.clear
@@ -71,15 +72,15 @@
   end
 
   describe '#merge' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
     it 'returns a merged hash of the context and the data' do
       expect(instance[:foo]).to eq 'bar'
       expect(instance.merge(baz: 'qux')).to include(foo: 'bar', baz: 'qux')
     end
   end
 
   describe '#merge' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
 
     context 'with valid keys in the hash' do
       it 'updates the context with the merged data' do
@@ -110,7 +111,7 @@
   end
 
   describe '#overwrite!' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
 
     context 'with valid keys in the hash' do
       it 'replaces the context with new data, preserving keys that already exist' do
@@ -129,16 +130,24 @@
   end
 
   describe '#scrub!' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
     it 'scrubs the data' do
       expect(dummy_scrubber).to receive(:scrub).with(foo: 'bar')
       subject.scrub!
     end
   end
 
+  describe '#normalize!' do
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
+    it 'normalizes the data' do
+      expect(dummy_normalizer).to receive(:normalize).with(foo: 'bar')
+      subject.normalize!
+    end
+  end
+
   describe 'to_h' do
-    subject(:instance) { described_class.new(dummy_scrubber, foo: 'bar') }
-    it 'returnst he data as a hash' do
+    subject(:instance) { described_class.new(dummy_scrubber, dummy_normalizer, foo: 'bar') }
+    it 'returns the data as a hash' do
       expect(instance.to_h).to include(foo: 'bar')
     end
   end

spec/hedgelog/normalizer_spec.rb

@@ -0,0 +1,62 @@
+require 'spec_helper'
+require 'hedgelog/normalizer'
+
+describe Hedgelog::Normalizer do
+  subject(:instance) { described_class.new }
+  let(:struct_class) { Struct.new(:foo, :bar) }
+  let(:struct) { struct_class.new(1234, 'dummy') }
+  let(:hash) { {message: 'dummy=1234'} }
+  let(:array) { ['dummy string', {message: 'dummy=1234'}] }
+  describe '#normalize' do
+    it 'returns the normalized data' do
+      expect(instance.normalize(hash)).to include(message: 'dummy=1234')
+    end
+
+    it 'does not modify external state' do
+      myvar = 'dummy=1234'
+      orig_myvar = myvar.clone
+
+      data = {foo: myvar}
+      instance.normalize(data)
+      expect(myvar).to eq orig_myvar
+    end
+  end
+  describe '#normalize_hash' do
+    it 'returns a normalized hash' do
+      expect(instance.normalize_hash(hash)).to include(message: 'dummy=1234')
+    end
+  end
+  describe '#normalize_struct' do
+    it 'returns struct as a normalized hash' do
+      expect(instance.normalize_struct(struct)).to include(foo: 1234, bar: 'dummy')
+    end
+  end
+  describe '#normalize_array' do
+    it 'returns array as a json string' do
+      normalized_array = instance.normalize_array(array)
+      expect(normalized_array).to be_a String
+      expect(normalized_array).to eq '["dummy string",{"message":"dummy=1234"}]'
+    end
+  end
+  context 'When a hash contains different types of data' do
+    let(:data) { hash }
+    before :each do
+      # add other types to the hash
+      data[:hash] = hash.clone
+      data[:struct] = struct
+      data[:array] = array
+      data[:string] = 'dummy'
+      data[:number] = 1234
+    end
+    it 'normalizes recursively' do
+      result = instance.normalize_hash(data)
+      expect(result[:hash]).to include(message: 'dummy=1234')
+      expect(result[:message]).to include('dummy=1234')
+      expect(result[:struct]).to be_a Hash
+      expect(result[:struct]).to include(foo: 1234, bar: 'dummy')
+      expect(result[:array]).to eq  '["dummy string",{"message":"dummy=1234"}]'
+      expect(result[:string]).to eq 'dummy'
+      expect(result[:number]).to eq 1234
+    end
+  end
+end

spec/hedgelog_spec.rb

@@ -278,46 +278,55 @@
     let(:log_dev) { '/dev/null' }
     let(:standard_logger) { Logger.new(log_dev) }
     let(:hedgelog_logger) { Hedgelog.new(log_dev) }
+    let(:message) { 'log message' }
+    let(:hedgelog_params) { [message] }
 
-    context 'when logging a string' do
-      let(:message) { 'log message' }
-
-      context 'when in debug mode' do
-        it 'is not be more than 12x slower than standard ruby logger' do
-          report = Benchmark.ips(quiet: true) do |bm|
-            bm.config(time: 5, warmup: 2)
-            bm.report('standard_logger') { standard_logger.debug(message) }
-            bm.report('hedgelog_logger') { hedgelog_logger.debug(message) }
-          end
+    before :each do
+      standard_logger.level = level
+      hedgelog_logger.level = level
+    end
 
-          standard_benchmark, hedgelog_benchmark = *report.entries
+    shared_context 'logging with context' do
+      let(:hash) { {message: 'dummy=1234'} }
+      let(:array) { ['dummy string', {message: 'dummy=1234'}] }
+      let(:context) { hash }
+      let(:hedgelog_params) { [message, context] }
+      before :each do
+        # add other types to the hash
+        context[:hash] = hash.clone
+        context[:array] = array
+        context[:string] = 'dummy'
+        context[:number] = 1234
+      end
+    end
 
-          expect(hedgelog_benchmark.ips).to be > (standard_benchmark.ips / 12)
+    context 'when in debug mode' do
+      let(:level) { Logger::DEBUG }
+      context 'when logging a string' do
+        it 'is no more than 12x slower than the stdlib logger' do
+          expect { standard_logger.debug(message) }.to perform.times_slower(12).than { hedgelog_logger.debug(*hedgelog_params) }
         end
       end
+      context 'when logging with context' do
+        include_context 'logging with context'
 
-      context 'when not in debug mode' do
-        let(:standard_logger) do
-          logger = Logger.new(log_dev)
-          logger.level = Logger::INFO
-          logger
+        it 'is no more than 16x slower than the stdlib logger' do
+          expect { standard_logger.debug(message) }.to perform.times_slower(16).than { hedgelog_logger.debug(*hedgelog_params) }
         end
-        let(:hedgelog_logger) do
-          logger = Hedgelog.new(log_dev)
-          logger.level = Logger::INFO
-          logger
+      end
+    end
+    context 'when not in debug mode' do
+      let(:level) { Logger::INFO }
+      context 'when logging a string' do
+        it 'is no more than 5x slower than the stdlib logger' do
+          expect { standard_logger.info(message) }.to perform.times_slower(5).than { hedgelog_logger.info(*hedgelog_params) }
         end
+      end
+      context 'when logging with context' do
+        include_context 'logging with context'
 
-        it 'is not be more than 5x slower than standard ruby logger' do
-          report = Benchmark.ips(quiet: true) do |bm|
-            bm.config(time: 5, warmup: 2)
-            bm.report('standard_logger') { standard_logger.info(message) }
-            bm.report('hedgelog_logger') { hedgelog_logger.info(message) }
-          end
-
-          standard_benchmark, hedgelog_benchmark = *report.entries
-
-          expect(hedgelog_benchmark.ips).to be > (standard_benchmark.ips / 5)
+        it 'is no more than 12x slower than the stdlib logger' do
+          expect { standard_logger.info(message) }.to perform.times_slower(12).than { hedgelog_logger.info(*hedgelog_params) }
         end
       end
     end

spec/spec_helper.rb

@@ -3,4 +3,10 @@
 require 'simplecov'
 require 'hedgelog'
 
+Dir[File.expand_path(File.join(File.dirname(__FILE__), 'support', '**', '*.rb'))].each { |f| require f }
+
 SimpleCov.start
+
+RSpec.configure do |config|
+  config.include Matchers::Benchmark
+end

spec/support/matchers/benchmark.rb

@@ -0,0 +1,44 @@
+require 'rspec/expectations'
+require 'benchmark/ips'
+
+module Matchers
+  module Benchmark
+    extend RSpec::Matchers::DSL
+
+    matcher :perform do
+      match do |block_arg|
+        report = ::Benchmark.ips(quiet: true) do |bm|
+          bm.config(time: 5, warmup: 2)
+          bm.report('first') { @second_block.call }
+          bm.report('second') { block_arg.call }
+        end
+
+        @first_bm, @second_bm = *report.entries
+
+        @first_bm.ips >= target_ips(@second_bm)
+      end
+
+      chain :times_slower do |slower|
+        @slower = slower
+      end
+
+      chain :than do |&blk|
+        @second_block = blk
+      end
+
+      failure_message do
+        "expected function to perform #{target_ips(@second_bm)} IPS, but it only performed #{@first_bm.ips} IPS"
+      end
+
+      def target_ips(result)
+        result.ips / (@slower || 1)
+      end
+
+      def supports_block_expectations?
+        true
+      end
+
+      diffable
+    end
+  end
+end